frodovdr/vdr
1
0
Fork 0
mirror of https://github.com/VDR4Arch/vdr.git synced 2023-10-10 13:36:52 +02:00
Code Issues Releases Wiki Activity

Added backtrace functions for debugging

Browse Source
This commit is contained in:
Klaus Schmidinger 2017-06-03 12:43:22 +02:00
parent bae02358a3
commit 2c74a31afe
5 changed files with 234 additions and 95 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
CONTRIBUTORS
View File

@ -3429,6 +3429,8 @@ Jasmin Jessich <jasmin@anw.at>
for help and suggestions when implementing debug output for checking the correct
sequence of locking global lists
for suggesting to use $(Q) to control Makefile verbosity
for adding handling DEBUG to the Make.config.template file, in order to control
code optimization
Martin Schirrmacher <schirrmie@gmail.com>
for suggesting to provide a way for skin plugins to get informed about the currently

20
HISTORY
View File

@ -9058,11 +9058,21 @@ Video Disk Recorder Revision History
2017-05-31: Version 2.3.6
- Added debug output for checking the correct sequence of locking global lists
(with help and suggestions from Jasmin Jessich). To activate this, define the
macro DEBUG_LOCKSEQ in thread.c. At the first occurrence of an invalid locking
sequence, the 20 most recent locks will be printed to stderr, followed by a
backtrace that led to the call in question.
- Added backtrace functions for debugging (see cBackTrace in thread.h).
- Added checking the correct sequence of locking global lists (with help and
suggestions from Jasmin Jessich). At the first occurrence of an invalid locking
sequence, the 20 most recent locks will be written to the log file, followed by a
backtrace that led to the call in question. This code can be activated by defining
the macro DEBUG_LOCKSEQ in thread.c (which is on by default).
When debugging an actual invalid locking sequence, you can additionally define
the macro DEBUG_LOCKCALL in thread.c, which will add information about the caller
of each lock. Note that this may cause some stress on the CPU, therefore it is off
by default.
- The file Make.config.template now reacts on DEBUG=1 in the 'make' command line,
and disables code optimizations by setting -O0 (thanks to Jasmin Jessich).
This can be helpful when backtracing highly optimized code. You may want to
'make distclean' before running 'make' with a modified setting of DEBUG, to make
sure all object files are newly compiled.
- Fixed the locking sequence when dumping EPG data.
- Fixed the locking sequence when starting a recording.
- The Makefiles now use the macro $(Q) instead of a plain '@' in front of their

8
Make.config.template
View File

@ -6,7 +6,7 @@
# See the main source file 'vdr.c' for copyright information and
# how to reach the author.
#
# $Id: Make.config.template 3.4 2015/02/09 09:58:45 kls Exp $
# $Id: Make.config.template 4.1 2017/06/02 09:29:54 kls Exp $
### The C compiler and options:
@ -16,6 +16,12 @@ CFLAGS = -g -O3 -Wall
CXX = g++
CXXFLAGS = -g -O3 -Wall -Werror=overloaded-virtual -Wno-parentheses
# Use 'make DEBUG=1 ...' to build a debug version of VDR and plugins:
ifdef DEBUG
CFLAGS += -O0
CXXFLAGS += -O0
endif
# Use 'make M32=1 ...' to build a 32-bit version of VDR on a 64-bit machine:
ifdef M32
CFLAGS += -m32

266
thread.c
View File

@ -4,27 +4,31 @@
* See the main source file 'vdr.c' for copyright information and
* how to reach the author.
*
* $Id: thread.c 4.3 2017/05/28 12:41:03 kls Exp $
* $Id: thread.c 4.4 2017/06/03 12:43:22 kls Exp $
*/
#include "thread.h"
#include <cxxabi.h>
#include <dlfcn.h>
#include <errno.h>
#include <execinfo.h>
#include <linux/unistd.h>
#include <malloc.h>
#include <stdarg.h>
#include <stdlib.h>
#include <sys/prctl.h>
#include <sys/resource.h>
#include <sys/syscall.h>
#include <sys/time.h>
#include <sys/wait.h>
#include <sys/prctl.h>
#include <unistd.h>
#include "tools.h"
#define ABORT { dsyslog("ABORT!"); abort(); } // use debugger to trace back the problem
#define ABORT { dsyslog("ABORT!"); cBackTrace::BackTrace(); abort(); }
//#define DEBUG_LOCKING // uncomment this line to activate debug output for locking
//#define DEBUG_LOCKSEQ // uncomment this line to activate debug output for locking sequence
//#define DEBUG_LOCKING // uncomment this line to activate debug output for locking
#define DEBUG_LOCKSEQ // uncomment this line to activate debug output for invalid locking sequence
//#define DEBUG_LOCKCALL // uncomment this line to activate caller information with DEBUG_LOCKSEQ (WARNING: expensive operation, use only when actually debugging the locking sequence!)
#ifdef DEBUG_LOCKING
#define dbglocking(a...) fprintf(stderr, a)
@ -430,27 +434,15 @@ bool cThreadLock::Lock(cThread *Thread)
return false;
}
// --- cStateLock ------------------------------------------------------------
// --- cBackTrace ------------------------------------------------------------
#ifdef DEBUG_LOCKSEQ
#include <cxxabi.h>
#include <execinfo.h>
static cVector<tThreadId> StateLockThreadIds;
static cVector<int> StateLockFlags;
static cMutex StateLockMutex;
#define SLL_SIZE 20 // the number of log entries
#define SLL_LENGTH 256 // the maximum length of log entries
#define SLL_DELIM '#' // delimiter for caller info
static char StateLockLog[SLL_SIZE][SLL_LENGTH] = { 0 };
static int StateLockLogIndex = 0;
static bool DumpStateLocks = true;
#define BT_BUF_SIZE 100
static cString Demangle(char *s, char *Prefix = NULL)
cString cBackTrace::Demangle(char *s)
{
char *Module = s;
char *Function = NULL;
//char *Offset = NULL;
char *Offset = NULL;
char *Address = NULL;
// separate the string:
for (char *q = Module; *q; q++) {
@ -460,7 +452,7 @@ static cString Demangle(char *s, char *Prefix = NULL)
}
else if (*q == '+') {
*q = 0;
//Offset = q + 1;
Offset = q + 1;
}
else if (*q == ')')
*q = 0;
@ -472,20 +464,46 @@ static cString Demangle(char *s, char *Prefix = NULL)
}
}
// demangle the function name:
int status;
char *r = abi::__cxa_demangle(Function, NULL, 0, &status);
if (r)
Function = r;
cString d = cString::sprintf("%s %s %s", Prefix ? Prefix : "", Module, Function);
char *DemangledFunction = NULL;
if (Function) {
int status;
DemangledFunction = abi::__cxa_demangle(Function, NULL, 0, &status);
if (DemangledFunction)
Function = DemangledFunction;
if (!*Function)
Function = NULL;
}
cString d = cString::sprintf("%s%s%s", Module, Function ? " " : "", Function ? Function : "");
// convert string address to numbers:
unsigned long long addr = Address ? strtoull(Address, NULL, 0) : 0;
unsigned long long offs = Offset ? strtoull(Offset, NULL, 0) : 0;
// for shared libraries we need get the offset inside the library:
if (Function) {
// check whether the module name ends with ".so*":
char *e = Module;
char *p = NULL;
while (e = strstr(e, ".so"))
p = e++;
if (p && !strchr(p, '/')) {
Dl_info dlinfo;
if (dladdr(reinterpret_cast<void*>(addr), &dlinfo)) {
if ((strcmp(Module, dlinfo.dli_fname) == 0) && dlinfo.dli_fbase) {
unsigned long long base = reinterpret_cast<unsigned long long>(dlinfo.dli_fbase);
addr -= base;
addr &= 0x0FFFFFFFF; // to make it work on both 32 and 64 bit systems
}
}
}
}
// determine the file name and line number:
cString cmd = cString::sprintf("addr2line --exe=%s --functions --demangle --basename %s", Module, Address);
cString cmd = cString::sprintf("addr2line --functions --demangle --inlines --basename --exe=%s 0x%llx", Module, Function ? addr : offs);
cPipe p;
if (p.Open(cmd, "r")) {
int n = 0;
cReadLine rl;
while (char *l = rl.Read(p)) {
if (n == 0) {
if (!isempty(Function) && strcmp(l, Function))
if (Function && strcmp(l, Function))
d = cString::sprintf("%s calling %s", *d, l);
}
else
@ -494,101 +512,173 @@ static cString Demangle(char *s, char *Prefix = NULL)
}
p.Close();
}
free(r);
free(DemangledFunction);
return d;
}
static void BackTrace(void)
void cBackTrace::BackTrace(cStringList &StringList, int Level, bool Mangled)
{
void *b[BT_BUF_SIZE];
int n = backtrace(b, BT_BUF_SIZE);
if (char **s = backtrace_symbols(b, n)) {
for (int i = 5; i < n; i++)
fprintf(stderr, "%s\n", *Demangle(s[i]));
for (int i = max(Level, 0) + 1; i < n; i++) // 1 is the call to this function itself
StringList.Append(strdup(Mangled ? s[i] : *Demangle(s[i])));
free(s);
}
}
static void BackTraceCaller(int Level, char *t, int l)
void cBackTrace::BackTrace(FILE *f, int Level, bool Mangled)
{
void *b[BT_BUF_SIZE];
int n = backtrace(b, BT_BUF_SIZE);
if (char **s = backtrace_symbols(b, n)) {
strn0cpy(t, s[Level], l);
free(s);
}
}
static void DumpStateLockLog(tThreadId ThreadId, const char *Name)
{
if (!DumpStateLocks)
return;
DumpStateLocks = false;
for (int i = 0; i < SLL_SIZE; i++) {
char *s = StateLockLog[StateLockLogIndex];
if (*s) {
if (char *Delim = strchr(s, SLL_DELIM)) {
*Delim = 0;
fprintf(stderr, "%s\n", *Demangle(Delim + 1, s));
}
}
if (++StateLockLogIndex >= SLL_SIZE)
StateLockLogIndex = 0;
cStringList sl;
BackTrace(sl, Level + 1, Mangled); // 1 is the call to this function itself
for (int i = 0; i < sl.Size(); i++) {
if (f)
fprintf(f, "%s\n", sl[i]);
else
dsyslog("%s", sl[i]);
}
fprintf(stderr, "%5d invalid lock sequence: %-12s\n", ThreadId, Name);
fprintf(stderr, "full backtrace:\n");
BackTrace();
}
static void CheckStateLockLevel(const char *Name, bool Lock, bool Write = false)
cString cBackTrace::GetCaller(int Level, bool Mangled)
{
if (Name) {
cString Caller;
Level = max(Level, 0) + 1; // 1 is the call to this function itself
void *b[BT_BUF_SIZE];
int n = backtrace(b, BT_BUF_SIZE);
if (char **s = backtrace_symbols(b, n)) {
if (Level < n)
Caller = Mangled ? s[Level] : *Demangle(s[Level]);
free(s);
}
return Caller;
}
// --- cStateLockLog ---------------------------------------------------------
#ifdef DEBUG_LOCKSEQ
#define SLL_SIZE 20 // the number of log entries
#define SLL_LENGTH 256 // the maximum length of log entries
#define SLL_MAX_LIST 9 // max. number of lists to log
#define SLL_WRITE_FLAG 0x80000000
class cStateLockLog {
private:
cMutex mutex;
cVector<tThreadId> threadIds;
cVector<int> flags;
tThreadId logThreadIds[SLL_SIZE];
int logFlags[SLL_SIZE];
char logCaller[SLL_SIZE][SLL_LENGTH];
int logIndex;
bool dumped;
void Dump(const char *Name, tThreadId ThreadId);
public:
cStateLockLog(void);
void Check(const char *Name, bool Lock, bool Write = false);
};
cStateLockLog::cStateLockLog(void)
{
memset(logThreadIds, 0, sizeof(logThreadIds));
memset(logFlags, 0, sizeof(logFlags));
memset(logCaller, 0, sizeof(logCaller));
logIndex = 0;
dumped = false;
}
void cStateLockLog::Dump(const char *Name, tThreadId ThreadId)
{
dsyslog("--- begin invalid lock sequence report");
int LastFlags = 0;
for (int i = 0; i < SLL_SIZE; i++) {
if (tThreadId tid = logThreadIds[logIndex]) {
char msg[SLL_LENGTH];
char *q = msg;
q += sprintf(q, "%5d", tid);
int Flags = logFlags[logIndex];
bool Write = Flags & SLL_WRITE_FLAG;
Flags &= ~SLL_WRITE_FLAG;
int Changed = LastFlags ^ Flags;
LastFlags = Flags;
bool Lock = (Flags & Changed) != 0;
for (int i = 0; i <= SLL_MAX_LIST; i++) {
char c = '-';
int b = 1 << i;
if ((Flags & b) != 0)
c = '*';
if ((Changed & b) != 0)
c = Lock ? Write ? 'W' : 'R' : '-';
q += sprintf(q, " %c", c);
}
q += sprintf(q, " %c", Lock ? 'L' : 'U');
if (*logCaller[logIndex]) {
*q++ = ' ';
strn0cpy(q, *cBackTrace::Demangle(logCaller[logIndex]), sizeof(msg) - (q - msg));
}
dsyslog("%s", msg);
}
if (++logIndex >= SLL_SIZE)
logIndex = 0;
}
dsyslog("%5d invalid lock sequence: %s", ThreadId, Name);
dsyslog("full backtrace:");
cBackTrace::BackTrace(NULL, 2);
dsyslog("--- end invalid lock sequence report");
fprintf(stderr, "invalid lock sequence at %s\n", *DayDateTime(time(NULL)));
}
void cStateLockLog::Check(const char *Name, bool Lock, bool Write)
{
if (!dumped && Name) {
int n = *Name - '0';
if (1 <= n && n <= 9) {
if (1 <= n && n <= SLL_MAX_LIST) {
int b = 1 << (n - 1);
cMutexLock MutexLock(&StateLockMutex);
cMutexLock MutexLock(&mutex);
tThreadId ThreadId = cThread::ThreadId();
int Index = StateLockThreadIds.IndexOf(ThreadId);
int Index = threadIds.IndexOf(ThreadId);
if (Index < 0) {
if (Lock) {
Index = StateLockThreadIds.Size();
StateLockThreadIds.Append(ThreadId);
StateLockFlags.Append(0);
Index = threadIds.Size();
threadIds.Append(ThreadId);
flags.Append(0);
}
else
return;
}
char *p = StateLockLog[StateLockLogIndex];
char *q = p;
q += sprintf(q, "%5d", ThreadId);
for (int i = 0; i <= 9; i++) {
char c = '-';
if (StateLockFlags[Index] & (1 << i))
c = '*';
if (i == n - 1)
c = Lock ? Write ? 'W' : 'R' : '-';
q += sprintf(q, " %c", c);
}
q += sprintf(q, " %c%c", Lock ? 'L' : 'U', SLL_DELIM);
BackTraceCaller(Lock ? 5 : 3, q, SLL_LENGTH - (q - p));
if (++StateLockLogIndex >= SLL_SIZE)
StateLockLogIndex = 0;
bool DoDump = false;
if (Lock) {
if ((StateLockFlags[Index] & ~b) < b)
StateLockFlags[Index] |= b;
else if ((StateLockFlags[Index] & b) == 0)
DumpStateLockLog(ThreadId, Name);
if ((flags[Index] & ~b) < b) // thread holds only "smaller" locks -> OK
;
else if ((flags[Index] & b) == 0) // thread already holds "bigger" locks, so it may only re-lock one that it already has!
DoDump = true;
flags[Index] |= b;
}
else
StateLockFlags[Index] &= ~b;
flags[Index] &= ~b;
logThreadIds[logIndex] = ThreadId;
logFlags[logIndex] = flags[Index] | (Write ? SLL_WRITE_FLAG : 0);
#ifdef DEBUG_LOCKCALL
strn0cpy(logCaller[logIndex], cBackTrace::GetCaller(Lock ? 5 : 3, true), SLL_LENGTH);
#endif
if (++logIndex >= SLL_SIZE)
logIndex = 0;
if (DoDump) {
Dump(Name, ThreadId);
dumped = true;
}
}
}
}
#define dbglockseq(n, l, w) CheckStateLockLevel(n, l, w)
static cStateLockLog StateLockLog;
#define dbglockseq(n, l, w) StateLockLog.Check(n, l, w)
#else
#define dbglockseq(n, l, w)
#endif // DEBUG_LOCKSEQ
// --- cStateLock ------------------------------------------------------------
cStateLock::cStateLock(const char *Name)
:rwLock(true)
{

33
thread.h
View File

@ -4,7 +4,7 @@
* See the main source file 'vdr.c' for copyright information and
* how to reach the author.
*
* $Id: thread.h 4.2 2016/12/08 10:18:32 kls Exp $
* $Id: thread.h 4.3 2017/06/03 12:43:22 kls Exp $
*/
#ifndef __THREAD_H
@ -291,6 +291,37 @@ public:
int Close(void);
};
// cBackTrace can be used for debugging.
class cStringList;
class cString;
class cBackTrace {
public:
static cString Demangle(char *s);
///< Demangles the function name in the given string and returns the converted
///< version of s. s must be one of the strings returned by a call to
///< BackTrace() or GetCaller().
///< Note that this function works on the given string by inserting '\0'
///< characters to separate the individual parts. Therefore the string
///< will be modified upon return.
static void BackTrace(cStringList &StringList, int Level = 0, bool Mangled = false);
///< Produces a backtrace and stores it in the given StringList.
///< If Level is given, only calls up to the given value are listed.
///< If Mangled is true, the raw backtrace will be returned and you can use
///< Demangle() to make the function names readable.
static void BackTrace(FILE *f = NULL, int Level = 0, bool Mangled = false);
///< Produces a backtrace beginning at the given Level, and
///< writes it to the given file. If no file is given, the backtrace is
///< written to the logfile. If Mangled is true, the raw backtrace will
///< be printed/logged.
static cString GetCaller(int Level = 0, bool Mangled = false);
///< Returns the caller at the given Level (or the immediate caller,
///< if Level is 0).
///< If Mangled is true, the raw backtrace will be returned and you can use
///< Demangle() to make the function name readable.
};
// SystemExec() implements a 'system()' call that closes all unnecessary file
// descriptors in the child process.
// With Detached=true, calls command in background and in a separate session,