root/trunk/libffado/src/debugmodule/debugmodule.cpp

Revision 670, 14.7 kB (checked in by ppalmers, 15 years ago)

Implement a BackLog?. This is a buffer that stores the last debug messages,
regardless of whether their debuglevel is high enough or not. It can be used
to run programs at a low verbosity level, but print highly verbose output when
something goes wrong.

The buffer is a ringbuffer where the oldest message is overwritten when a new
one is added. The readout however is FIFO, oldest messages first.

Use the debugShowBackLog() macro when you want to print the backlog to stderr.

Note that the backlog is not thread safe so sometimes there might be some errors
in the lines, but it otherwise would require the introduction of more locks in
the critical path.

  • Property svn:eol-style set to native
  • Property svn:keywords set to Author Date Id Revision
Line 
1 /*
2  * Copyright (C) 2005-2007 by Daniel Wagner
3  * Copyright (C) 2005-2007 by Pieter Palmers
4  *
5  * This file is part of FFADO
6  * FFADO = Free Firewire (pro-)audio drivers for linux
7  *
8  * FFADO is based upon FreeBoB
9  *
10  * This library is free software; you can redistribute it and/or
11  * modify it under the terms of the GNU Lesser General Public
12  * License version 2.1, as published by the Free Software Foundation;
13  *
14  * This library is distributed in the hope that it will be useful,
15  * but WITHOUT ANY WARRANTY; without even the implied warranty of
16  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
17  * Lesser General Public License for more details.
18  *
19  * You should have received a copy of the GNU Lesser General Public
20  * License along with this library; if not, write to the Free Software
21  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston,
22  * MA 02110-1301 USA
23  */
24
25 #include "debugmodule.h"
26
27 #include <stdarg.h>
28 #include <netinet/in.h>
29
30 #include <iostream>
31
32 #include <time.h>
33
34 #define DO_MESSAGE_BUFFER_PRINT
35
36 #ifndef DO_MESSAGE_BUFFER_PRINT
37         #warning Printing debug info without ringbuffer, not RT-safe!
38 #endif
39
40 using namespace std;
41
42 struct ColorEntry  {
43     const char* preSequence;
44     const char* postSequence;
45 };
46
47 ColorEntry colorTable[] = {
48     { "\033[31mFatal",   "\033[0m" },
49     { "\033[31mError",   "\033[0m" },
50     { "\033[31mWarning", "\033[0m" },
51     { "Debug",           ""        },
52 };
53
54
55 DebugModule::DebugModule( std::string name,  debug_level_t level )
56     : m_name( name )
57     , m_level( level )
58 {
59     if ( !DebugModuleManager::instance()->registerModule( *this ) ) {
60         cerr << "Could not register DebugModule (" << name
61              << ") at DebugModuleManager"
62              << endl;
63     }
64 }
65
66 DebugModule::~DebugModule()
67 {
68 //     if ( m_level >= eDL_VeryVerbose ) {
69 //         cout << "Unregistering "
70 //              << this->getName()
71 //              << " at DebugModuleManager"
72 //              << endl;
73 //     }
74     if ( !DebugModuleManager::instance()->unregisterModule( *this ) ) {
75         cerr << "Could not unregister DebugModule at DebugModuleManager"
76              << endl;
77     }
78
79 }
80
81 void
82 DebugModule::printShort( debug_level_t level,
83                          const char* format,
84                          ... ) const
85 {
86     if ( level > m_level ) {
87         return;
88     }
89
90     va_list arg;
91
92     va_start( arg, format );
93
94     DebugModuleManager::instance()->va_print( format, arg );
95
96     va_end( arg );
97 }
98
99 void
100 DebugModule::print( debug_level_t level,
101                     const char*   file,
102                     const char*   function,
103                     unsigned int  line,
104                     const char*   format,
105                     ... ) const
106 {
107     if ( level > m_level ) {
108         return;
109     }
110
111     va_list arg;
112     va_start( arg, format );
113
114     // remove the path info from the filename
115     const char *f = file;
116     const char *fname = file;
117     while((f=strstr(f, "/"))) {
118         f++; // move away from delimiter
119         fname=f;
120     }
121    
122     // add a timing timestamp
123     struct timespec ts;
124     clock_gettime(CLOCK_MONOTONIC, &ts);
125     uint32_t ts_usec=(uint32_t)(ts.tv_sec * 1000000LL + ts.tv_nsec / 1000LL);
126    
127     DebugModuleManager::instance()->print( "%010lu: %s (%s)[%4d] %s: ",
128                  ts_usec, getPreSequence( level ),
129                  fname,  line,  function );
130     DebugModuleManager::instance()->va_print( format, arg );
131     DebugModuleManager::instance()->print( "%s", getPostSequence( level ) );
132     va_end( arg );
133 }
134
135 const char*
136 DebugModule::getPreSequence( debug_level_t level ) const
137 {
138     if ( ( level <= eDL_Normal ) && ( level >= eDL_Fatal ) ) {
139         return colorTable[level].preSequence;
140     }
141     return colorTable[eDL_Normal].preSequence;
142 }
143
144 const char*
145 DebugModule::getPostSequence( debug_level_t level ) const
146 {
147     if ( ( level <= eDL_Normal ) && ( level >= eDL_Fatal ) ) {
148         return colorTable[level].postSequence;
149     }
150     return colorTable[eDL_Normal].postSequence;
151 }
152
153 //--------------------------------------
154
155 DebugModuleManager* DebugModuleManager::m_instance = 0;
156
157 DebugModuleManager::DebugModuleManager()
158     : mb_initialized(0)
159     , mb_inbuffer(0)
160     , mb_outbuffer(0)
161     , mb_overruns(0)
162     , bl_mb_inbuffer(0)
163 {
164
165 }
166
167 DebugModuleManager::~DebugModuleManager()
168 {
169     // cleanin up leftover modules
170     for ( DebugModuleVectorIterator it = m_debugModules.begin();
171           it != m_debugModules.end();
172           ++it )
173     {
174         fprintf(stderr,"Cleaning up leftover debug module: %s\n",(*it)->getName().c_str());
175         m_debugModules.erase( it );
176         delete *it;
177     }
178
179     if (!mb_initialized)
180         return;
181
182     pthread_mutex_lock(&mb_write_lock);
183     mb_initialized = 0;
184     pthread_cond_signal(&mb_ready_cond);
185     pthread_mutex_unlock(&mb_write_lock);
186
187     pthread_join(mb_writer_thread, NULL);
188     mb_flush();
189
190     if (mb_overruns)
191         fprintf(stderr, "WARNING: %d message buffer overruns!\n",
192             mb_overruns);
193     else
194         fprintf(stderr, "no message buffer overruns\n");
195
196     pthread_mutex_destroy(&mb_write_lock);
197     pthread_cond_destroy(&mb_ready_cond);
198
199 }
200
201 bool
202 DebugModuleManager::init()
203 {
204     if (mb_initialized)
205         return true;
206
207         // if ( m_level >= eDL_VeryVerbose )
208         //         cout << "DebugModuleManager init..." << endl;
209
210     pthread_mutex_init(&mb_write_lock, NULL);
211     pthread_mutex_init(&mb_flush_lock, NULL);
212     pthread_cond_init(&mb_ready_cond, NULL);
213
214     mb_overruns = 0;
215     mb_initialized = 1;
216
217     if (pthread_create(&mb_writer_thread, NULL, &mb_thread_func, (void *)this) != 0)
218          mb_initialized = 0;
219
220     return true;
221 }
222
223 DebugModuleManager*
224 DebugModuleManager::instance()
225 {
226     if ( !m_instance ) {
227         m_instance = new DebugModuleManager;
228         if ( !m_instance ) {
229             cerr << "DebugModuleManager::instance Failed to create "
230                  << "DebugModuleManager" << endl;
231         }
232         if ( !m_instance->init() ) {
233             cerr << "DebugModuleManager::instance Failed to init "
234                  << "DebugModuleManager" << endl;
235         }
236     }
237     return m_instance;
238 }
239
240 bool
241 DebugModuleManager::registerModule( DebugModule& debugModule )
242 {
243     bool already_present=false;
244
245     for ( DebugModuleVectorIterator it = m_debugModules.begin();
246           it != m_debugModules.end();
247           ++it )
248     {
249         if ( *it == &debugModule ) {
250             already_present=true;
251             return true;
252         }
253     }
254
255     if (already_present) {
256         cerr << "DebugModuleManager::registerModule: Module already registered: "
257             << "DebugModule (" << debugModule.getName() << ")" << endl;
258     } else {
259         m_debugModules.push_back( &debugModule );
260     }
261     return true;
262 }
263
264 bool
265 DebugModuleManager::unregisterModule( DebugModule& debugModule )
266 {
267
268     for ( DebugModuleVectorIterator it = m_debugModules.begin();
269           it != m_debugModules.end();
270           ++it )
271     {
272         if ( *it == &debugModule ) {
273             m_debugModules.erase( it );
274             return true;
275         }
276     }
277
278     cerr << "DebugModuleManager::unregisterModule: Could not unregister "
279          << "DebugModule (" << debugModule.getName() << ")" << endl;
280     return false;
281 }
282
283 bool
284 DebugModuleManager::setMgrDebugLevel( std::string name, debug_level_t level )
285 {
286     for ( DebugModuleVectorIterator it = m_debugModules.begin();
287           it != m_debugModules.end();
288           ++it )
289     {
290         if ( (*it)->getName() == name ) {
291             return (*it)->setLevel( level );
292         }
293     }
294
295     cerr << "setDebugLevel: Did not find DebugModule ("
296          << name << ")" << endl;
297     return false;
298 }
299
300 void
301 DebugModuleManager::flush()
302 {
303 #ifdef DO_MESSAGE_BUFFER_PRINT
304     mb_flush();
305 #else
306     fflush(stderr);
307 #endif
308 }
309
310 void
311 DebugModuleManager::mb_flush()
312 {
313     /* called WITHOUT the mb_write_lock */
314    
315     /* the flush lock is to allow a flush from multiple threads
316      * this allows a code section that outputs a lot of debug messages
317      * and that can be blocked to flush the buffer itself such that it
318      * does not overflow.
319      */
320     DebugModuleManager *m=DebugModuleManager::instance();
321     pthread_mutex_lock(&m->mb_flush_lock);
322     while (mb_outbuffer != mb_inbuffer) {
323         fputs(mb_buffers[mb_outbuffer], stderr);
324         mb_outbuffer = MB_NEXT(mb_outbuffer);
325     }
326     pthread_mutex_unlock(&m->mb_flush_lock);
327 }
328
329 void
330 DebugModuleManager::showBackLog()
331 {
332     DebugModuleManager *m=DebugModuleManager::instance();
333     fprintf(stderr, "=====================================================\n");
334     fprintf(stderr, "* BEGIN OF BACKLOG PRINT\n");
335     fprintf(stderr, "=====================================================\n");
336
337     for (unsigned int i=0; i<BACKLOG_MB_BUFFERS;i++) {
338         unsigned int idx=(i+bl_mb_inbuffer)%BACKLOG_MB_BUFFERS;
339         fputs(bl_mb_buffers[idx], stderr);
340     }
341     fprintf(stderr, "\n");
342    
343     fprintf(stderr, "=====================================================\n");
344     fprintf(stderr, "* END OF BACKLOG PRINT\n");
345     fprintf(stderr, "=====================================================\n");
346 }
347
348 void *
349 DebugModuleManager::mb_thread_func(void *arg)
350 {
351
352     DebugModuleManager *m=static_cast<DebugModuleManager *>(arg);
353
354     /* The mutex is only to eliminate collisions between multiple
355      * writer threads and protect the condition variable. */
356      pthread_mutex_lock(&m->mb_write_lock);
357
358     while (m->mb_initialized) {
359          pthread_cond_wait(&m->mb_ready_cond, &m->mb_write_lock);
360
361          /* releasing the mutex reduces contention */
362          pthread_mutex_unlock(&m->mb_write_lock);
363          m->mb_flush();
364          pthread_mutex_lock(&m->mb_write_lock);
365     }
366
367      pthread_mutex_unlock(&m->mb_write_lock);
368
369     return NULL;
370 }
371
372 void
373 DebugModuleManager::print(const char *fmt, ...)
374 {
375     char msg[MB_BUFFERSIZE];
376     va_list ap;
377
378 #ifdef DO_MESSAGE_BUFFER_PRINT
379     unsigned int ntries;
380     struct timespec wait = {0,50000};
381 #endif
382
383     /* format the message first, to reduce lock contention */
384     va_start(ap, fmt);
385     if (vsnprintf(msg, MB_BUFFERSIZE, fmt, ap) >= MB_BUFFERSIZE) {
386         print("WARNING: message truncated!\n");
387     }
388     va_end(ap);
389
390     if (!mb_initialized) {
391         /* Unable to print message with realtime safety.
392          * Complain and print it anyway. */
393         fprintf(stderr, "ERROR: messagebuffer not initialized: %s",
394             msg);
395         return;
396     }
397    
398     // the backlog
399     strncpy(bl_mb_buffers[bl_mb_inbuffer], msg, BACKLOG_MB_BUFFERSIZE);
400     bl_mb_inbuffer = BACKLOG_MB_NEXT(bl_mb_inbuffer);
401    
402 #ifdef DO_MESSAGE_BUFFER_PRINT
403     ntries=5;
404     while (ntries) { // try a few times
405         if (pthread_mutex_trylock(&mb_write_lock) == 0) {
406             strncpy(mb_buffers[mb_inbuffer], msg, MB_BUFFERSIZE);
407             mb_inbuffer = MB_NEXT(mb_inbuffer);
408             pthread_cond_signal(&mb_ready_cond);
409             pthread_mutex_unlock(&mb_write_lock);
410             break;
411         } else {
412             nanosleep(&wait, NULL);
413             ntries--;
414         }
415     }
416     if (ntries==0) {  /* lock collision */
417         //         atomic_add(&mb_overruns, 1);
418         // FIXME: atomicity
419         mb_overruns++; // skip the atomicness for now
420     }
421 #else
422     fprintf(stderr,msg);
423 #endif
424 }
425
426 void
427 DebugModuleManager::va_print (const char *fmt, va_list ap)
428 {
429     char msg[MB_BUFFERSIZE];
430
431 #ifdef DO_MESSAGE_BUFFER_PRINT
432     unsigned int ntries;
433     struct timespec wait = {0,50000};
434 #endif
435
436     /* format the message first, to reduce lock contention */
437     if (vsnprintf(msg, MB_BUFFERSIZE, fmt, ap) >= MB_BUFFERSIZE) {
438         print("WARNING: message truncated!\n");
439     }
440    
441     if (!mb_initialized) {
442         /* Unable to print message with realtime safety.
443          * Complain and print it anyway. */
444         fprintf(stderr, "ERROR: messagebuffer not initialized: %s",
445             msg);
446         return;
447     }
448    
449     // the backlog
450     strncpy(bl_mb_buffers[bl_mb_inbuffer], msg, BACKLOG_MB_BUFFERSIZE);
451     bl_mb_inbuffer = BACKLOG_MB_NEXT(bl_mb_inbuffer);
452
453 #ifdef DO_MESSAGE_BUFFER_PRINT
454     ntries=5;
455     while (ntries) { // try a few times
456         if (pthread_mutex_trylock(&mb_write_lock) == 0) {
457             strncpy(mb_buffers[mb_inbuffer], msg, MB_BUFFERSIZE);
458             mb_inbuffer = MB_NEXT(mb_inbuffer);
459             pthread_cond_signal(&mb_ready_cond);
460             pthread_mutex_unlock(&mb_write_lock);
461             break;
462         } else {
463             nanosleep(&wait, NULL);
464             ntries--;
465         }
466     }
467    
468     if (ntries==0) {  /* lock collision */
469 //         atomic_add(&mb_overruns, 1);
470         // FIXME: atomicity
471         mb_overruns++; // skip the atomicness for now
472     }
473 #else
474     fprintf(stderr,msg);
475 #endif
476 }
477
478 //----------------------------------------
479
480 unsigned char
481 toAscii( unsigned char c )
482 {
483     if ( ( c > 31 ) && ( c < 126) ) {
484         return c;
485     } else {
486         return '.';
487     }
488 }
489
490 /* converts a quadlet to a uchar * buffer
491  * not implemented optimally, but clear
492  */
493 void
494 quadlet2char( quadlet_t quadlet, unsigned char* buff )
495 {
496     *(buff)   = (quadlet>>24)&0xFF;
497     *(buff+1) = (quadlet>>16)&0xFF;
498     *(buff+2) = (quadlet>> 8)&0xFF;
499     *(buff+3) = (quadlet)    &0xFF;
500 }
501
502 void
503 hexDump( unsigned char *data_start, unsigned int length )
504 {
505     unsigned int i=0;
506     unsigned int byte_pos;
507     unsigned int bytes_left;
508
509     if ( length <= 0 ) {
510         return;
511     }
512     if ( length >= 7 ) {
513         for ( i = 0; i < (length-7); i += 8 ) {
514             printf( "%04X: %02X %02X %02X %02X %02X %02X %02X %02X "
515                     "- [%c%c%c%c%c%c%c%c]\n",
516
517                     i,
518
519                     *(data_start+i+0),
520                     *(data_start+i+1),
521                     *(data_start+i+2),
522                     *(data_start+i+3),
523                     *(data_start+i+4),
524                     *(data_start+i+5),
525                     *(data_start+i+6),
526                     *(data_start+i+7),
527
528                     toAscii( *(data_start+i+0) ),
529                     toAscii( *(data_start+i+1) ),
530                     toAscii( *(data_start+i+2) ),
531                     toAscii( *(data_start+i+3) ),
532                     toAscii( *(data_start+i+4) ),
533                     toAscii( *(data_start+i+5) ),
534                     toAscii( *(data_start+i+6) ),
535                     toAscii( *(data_start+i+7) )
536                 );
537         }
538     }
539     byte_pos = i;
540     bytes_left = length - byte_pos;
541
542     printf( "%04X:" ,i );
543     for ( i = byte_pos; i < length; i += 1 ) {
544         printf( " %02X", *(data_start+i) );
545     }
546     for ( i=0; i < 8-bytes_left; i+=1 ) {
547         printf( "   " );
548     }
549
550     printf( " - [" );
551     for ( i = byte_pos; i < length; i += 1) {
552         printf( "%c", toAscii(*(data_start+i)));
553     }
554     for ( i = 0; i < 8-bytes_left; i += 1) {
555         printf( " " );
556     }
557
558     printf( "]" );
559     printf( "\n" );
560 }
561
562 void
563 hexDumpQuadlets( quadlet_t *data, unsigned int length )
564 {
565     unsigned int i=0;
566
567     if ( length <= 0 ) {
568         return;
569     }
570     for (i = 0; i< length; i += 1) {
571         printf( "%02d %04X: %08X (%08X)"
572                 "\n", i, i*4, data[i],ntohl(data[i]));
573     }
574 }
575
576
Note: See TracBrowser for help on using the browser.