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

Revision 698, 17.1 kB (checked in by ppalmers, 15 years ago)

- make backlog a compile time option
- do some performance optimization on the debugging code

  • 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
87     // bypass for performance
88 #ifdef IMPLEMENT_BACKLOG
89     if (level > BACKLOG_MIN_LEVEL
90         && level > m_level) {
91         return;
92     }
93 #else
94     if ( level >m_level ) {
95         return;
96     }
97 #endif
98
99     const char *warning = "WARNING: message truncated!\n";
100     const int warning_size = 32;
101     va_list arg;
102     char msg[MB_BUFFERSIZE];
103
104     // format the message such that it remains together
105     int chars_written=0;
106     int retval=0;
107
108     va_start( arg, format );
109     retval = vsnprintf(msg+chars_written, MB_BUFFERSIZE, format, arg);
110     va_end( arg );
111     if (retval >= 0) {  // ignore errors
112         chars_written += retval;
113     }
114
115     // output a warning if the message was truncated
116     if (chars_written == MB_BUFFERSIZE) {
117         snprintf(msg+MB_BUFFERSIZE-warning_size, warning_size, "%s", warning);
118     }
119
120 #ifdef IMPLEMENT_BACKLOG
121     // print to backlog if necessary
122     if (level <= BACKLOG_MIN_LEVEL) {
123         DebugModuleManager::instance()->backlog_print( msg );
124     }
125 #endif
126
127     // print to stderr if necessary
128     if ( level <= m_level ) {
129         DebugModuleManager::instance()->print( msg );
130     }
131 }
132
133 void
134 DebugModule::print( debug_level_t level,
135                     const char*   file,
136                     const char*   function,
137                     unsigned int  line,
138                     const char*   format,
139                     ... ) const
140 {
141     // bypass for performance
142 #ifdef IMPLEMENT_BACKLOG
143     if (level > BACKLOG_MIN_LEVEL
144         && level > m_level) {
145         return;
146     }
147 #else
148     if ( level >m_level ) {
149         return;
150     }
151 #endif
152
153     const char *warning = "WARNING: message truncated!\n";
154     const int warning_size = 32;
155
156     va_list arg;
157     char msg[MB_BUFFERSIZE];
158
159     // remove the path info from the filename
160     const char *f = file;
161     const char *fname = file;
162     while((f=strstr(f, "/"))) {
163         f++; // move away from delimiter
164         fname=f;
165     }
166
167     // add a timing timestamp
168     struct timespec ts;
169     clock_gettime(CLOCK_MONOTONIC, &ts);
170     long unsigned int ts_usec=(uint32_t)(ts.tv_sec * 1000000LL + ts.tv_nsec / 1000LL);
171
172     // format the message such that it remains together
173     int chars_written=0;
174     int retval=0;
175     retval = snprintf(msg, MB_BUFFERSIZE, "%010lu: %s (%s)[%4d] %s: ",
176                       ts_usec, getPreSequence( level ),
177                       fname,  line,  function );
178     if (retval >= 0) chars_written += retval; // ignore errors
179
180     va_start( arg, format );
181     retval = vsnprintf( msg + chars_written,
182                         MB_BUFFERSIZE - chars_written,
183                         format, arg);
184     va_end( arg );
185     if (retval >= 0) chars_written += retval; // ignore errors
186
187     retval = snprintf( msg + chars_written,
188                        MB_BUFFERSIZE - chars_written,
189                        "%s", getPostSequence( level ) );
190     if (retval >= 0) chars_written += retval; // ignore errors
191
192     // output a warning if the message was truncated
193     if (chars_written == MB_BUFFERSIZE) {
194         snprintf(msg + MB_BUFFERSIZE - warning_size,
195                  warning_size,
196                  "%s", warning);
197     }
198
199 #ifdef IMPLEMENT_BACKLOG
200     // print to backlog if necessary
201     if (level <= BACKLOG_MIN_LEVEL) {
202         DebugModuleManager::instance()->backlog_print( msg );
203     }
204 #endif
205
206     // print to stderr if necessary
207     if ( level <= m_level ) {
208         DebugModuleManager::instance()->print( msg );
209     }
210 }
211
212 const char*
213 DebugModule::getPreSequence( debug_level_t level ) const
214 {
215     if ( ( level <= eDL_Normal ) && ( level >= eDL_Fatal ) ) {
216         return colorTable[level].preSequence;
217     }
218     return colorTable[eDL_Normal].preSequence;
219 }
220
221 const char*
222 DebugModule::getPostSequence( debug_level_t level ) const
223 {
224     if ( ( level <= eDL_Normal ) && ( level >= eDL_Fatal ) ) {
225         return colorTable[level].postSequence;
226     }
227     return colorTable[eDL_Normal].postSequence;
228 }
229
230 //--------------------------------------
231
232 DebugModuleManager* DebugModuleManager::m_instance = 0;
233
234 DebugModuleManager::DebugModuleManager()
235     : mb_initialized(0)
236     , mb_inbuffer(0)
237     , mb_outbuffer(0)
238     , mb_overruns(0)
239 #ifdef IMPLEMENT_BACKLOG
240     , bl_mb_inbuffer(0)
241 #endif
242 {
243
244 }
245
246 DebugModuleManager::~DebugModuleManager()
247 {
248     // cleanin up leftover modules
249     for ( DebugModuleVectorIterator it = m_debugModules.begin();
250           it != m_debugModules.end();
251           ++it )
252     {
253         fprintf(stderr,"Cleaning up leftover debug module: %s\n",(*it)->getName().c_str());
254         m_debugModules.erase( it );
255         delete *it;
256     }
257
258     if (!mb_initialized)
259         return;
260
261     pthread_mutex_lock(&mb_write_lock);
262     mb_initialized = 0;
263     pthread_cond_signal(&mb_ready_cond);
264     pthread_mutex_unlock(&mb_write_lock);
265
266     pthread_join(mb_writer_thread, NULL);
267     mb_flush();
268
269     if (mb_overruns)
270         fprintf(stderr, "WARNING: %d message buffer overruns!\n",
271             mb_overruns);
272     else
273         fprintf(stderr, "no message buffer overruns\n");
274
275     pthread_mutex_destroy(&mb_write_lock);
276     pthread_cond_destroy(&mb_ready_cond);
277
278 #ifdef IMPLEMENT_BACKLOG
279     pthread_mutex_destroy(&bl_mb_write_lock);
280 #endif
281
282 }
283
284 bool
285 DebugModuleManager::init()
286 {
287     if (mb_initialized)
288         return true;
289
290         // if ( m_level >= eDL_VeryVerbose )
291         //         cout << "DebugModuleManager init..." << endl;
292
293     pthread_mutex_init(&mb_write_lock, NULL);
294     pthread_mutex_init(&mb_flush_lock, NULL);
295     pthread_cond_init(&mb_ready_cond, NULL);
296
297     mb_overruns = 0;
298     mb_initialized = 1;
299
300 #ifdef IMPLEMENT_BACKLOG
301     pthread_mutex_init(&bl_mb_write_lock, NULL);
302 #endif
303
304     if (pthread_create(&mb_writer_thread, NULL, &mb_thread_func, (void *)this) != 0)
305          mb_initialized = 0;
306
307     return true;
308 }
309
310 DebugModuleManager*
311 DebugModuleManager::instance()
312 {
313     if ( !m_instance ) {
314         m_instance = new DebugModuleManager;
315         if ( !m_instance ) {
316             cerr << "DebugModuleManager::instance Failed to create "
317                  << "DebugModuleManager" << endl;
318         }
319         if ( !m_instance->init() ) {
320             cerr << "DebugModuleManager::instance Failed to init "
321                  << "DebugModuleManager" << endl;
322         }
323     }
324     return m_instance;
325 }
326
327 bool
328 DebugModuleManager::registerModule( DebugModule& debugModule )
329 {
330     bool already_present=false;
331
332     for ( DebugModuleVectorIterator it = m_debugModules.begin();
333           it != m_debugModules.end();
334           ++it )
335     {
336         if ( *it == &debugModule ) {
337             already_present=true;
338             return true;
339         }
340     }
341
342     if (already_present) {
343         cerr << "DebugModuleManager::registerModule: Module already registered: "
344             << "DebugModule (" << debugModule.getName() << ")" << endl;
345     } else {
346         m_debugModules.push_back( &debugModule );
347     }
348     return true;
349 }
350
351 bool
352 DebugModuleManager::unregisterModule( DebugModule& debugModule )
353 {
354
355     for ( DebugModuleVectorIterator it = m_debugModules.begin();
356           it != m_debugModules.end();
357           ++it )
358     {
359         if ( *it == &debugModule ) {
360             m_debugModules.erase( it );
361             return true;
362         }
363     }
364
365     cerr << "DebugModuleManager::unregisterModule: Could not unregister "
366          << "DebugModule (" << debugModule.getName() << ")" << endl;
367     return false;
368 }
369
370 bool
371 DebugModuleManager::setMgrDebugLevel( std::string name, debug_level_t level )
372 {
373     for ( DebugModuleVectorIterator it = m_debugModules.begin();
374           it != m_debugModules.end();
375           ++it )
376     {
377         if ( (*it)->getName() == name ) {
378             return (*it)->setLevel( level );
379         }
380     }
381
382     cerr << "setDebugLevel: Did not find DebugModule ("
383          << name << ")" << endl;
384     return false;
385 }
386
387 void
388 DebugModuleManager::flush()
389 {
390 #ifdef DO_MESSAGE_BUFFER_PRINT
391     mb_flush();
392 #else
393     fflush(stderr);
394 #endif
395 }
396
397 void
398 DebugModuleManager::mb_flush()
399 {
400     /* called WITHOUT the mb_write_lock */
401    
402     /* the flush lock is to allow a flush from multiple threads
403      * this allows a code section that outputs a lot of debug messages
404      * and that can be blocked to flush the buffer itself such that it
405      * does not overflow.
406      */
407     DebugModuleManager *m=DebugModuleManager::instance();
408     pthread_mutex_lock(&m->mb_flush_lock);
409     while (mb_outbuffer != mb_inbuffer) {
410         fputs(mb_buffers[mb_outbuffer], stderr);
411         mb_outbuffer = MB_NEXT(mb_outbuffer);
412     }
413     pthread_mutex_unlock(&m->mb_flush_lock);
414 }
415
416 #ifdef IMPLEMENT_BACKLOG
417 void
418 DebugModuleManager::showBackLog()
419 {
420      DebugModuleManager *m=DebugModuleManager::instance();
421     // locking the flush lock ensures that the backlog is
422     // printed as one entity
423     pthread_mutex_lock(&m->mb_flush_lock);
424     fprintf(stderr, "=====================================================\n");
425     fprintf(stderr, "* BEGIN OF BACKLOG PRINT\n");
426     fprintf(stderr, "=====================================================\n");
427
428     for (unsigned int i=0; i<BACKLOG_MB_BUFFERS;i++) {
429         unsigned int idx=(i+bl_mb_inbuffer)%BACKLOG_MB_BUFFERS;
430         fputs(bl_mb_buffers[idx], stderr);
431     }
432     fprintf(stderr, "\n");
433
434     fprintf(stderr, "=====================================================\n");
435     fprintf(stderr, "* END OF BACKLOG PRINT\n");
436     fprintf(stderr, "=====================================================\n");
437     pthread_mutex_unlock(&m->mb_flush_lock);
438 }
439
440 void
441 DebugModuleManager::showBackLog(int nblines)
442 {
443      DebugModuleManager *m=DebugModuleManager::instance();
444     // locking the flush lock ensures that the backlog is
445     // printed as one entity
446     pthread_mutex_lock(&m->mb_flush_lock);
447     fprintf(stderr, "=====================================================\n");
448     fprintf(stderr, "* BEGIN OF BACKLOG PRINT\n");
449     fprintf(stderr, "=====================================================\n");
450
451     int lines_to_skip = BACKLOG_MB_BUFFERS - nblines;
452     if (lines_to_skip < 0) lines_to_skip = 0;
453     for (unsigned int i=0; i<BACKLOG_MB_BUFFERS;i++) {
454         if (lines_to_skip-- < 0) {
455             unsigned int idx=(i+bl_mb_inbuffer)%BACKLOG_MB_BUFFERS;
456             fputs(bl_mb_buffers[idx], stderr);
457         }
458     }
459     fprintf(stderr, "\n");
460
461     fprintf(stderr, "=====================================================\n");
462     fprintf(stderr, "* END OF BACKLOG PRINT\n");
463     fprintf(stderr, "=====================================================\n");
464     pthread_mutex_unlock(&m->mb_flush_lock);
465 }
466 #endif
467
468 void *
469 DebugModuleManager::mb_thread_func(void *arg)
470 {
471
472     DebugModuleManager *m=static_cast<DebugModuleManager *>(arg);
473
474     /* The mutex is only to eliminate collisions between multiple
475      * writer threads and protect the condition variable. */
476      pthread_mutex_lock(&m->mb_write_lock);
477
478     while (m->mb_initialized) {
479          pthread_cond_wait(&m->mb_ready_cond, &m->mb_write_lock);
480
481          /* releasing the mutex reduces contention */
482          pthread_mutex_unlock(&m->mb_write_lock);
483          m->mb_flush();
484          pthread_mutex_lock(&m->mb_write_lock);
485     }
486
487      pthread_mutex_unlock(&m->mb_write_lock);
488
489     return NULL;
490 }
491
492 #ifdef IMPLEMENT_BACKLOG
493 void
494 DebugModuleManager::backlog_print(const char *msg)
495 {
496     unsigned int ntries;
497     struct timespec wait = {0,50000};
498     // the backlog
499     ntries=1;
500     while (ntries) { // try a few times
501         if (pthread_mutex_trylock(&bl_mb_write_lock) == 0) {
502             strncpy(bl_mb_buffers[bl_mb_inbuffer], msg, MB_BUFFERSIZE);
503             bl_mb_inbuffer = BACKLOG_MB_NEXT(bl_mb_inbuffer);
504             pthread_mutex_unlock(&bl_mb_write_lock);
505             break;
506         } else {
507             nanosleep(&wait, NULL);
508             ntries--;
509         }
510     }
511     // just bail out should it have failed
512 }
513 #endif
514
515 void
516 DebugModuleManager::print(const char *msg)
517 {
518 #ifdef DO_MESSAGE_BUFFER_PRINT
519     unsigned int ntries;
520     struct timespec wait = {0,50000};
521 #endif
522
523     if (!mb_initialized) {
524         /* Unable to print message with realtime safety.
525          * Complain and print it anyway. */
526         fprintf(stderr, "ERROR: messagebuffer not initialized: %s",
527             msg);
528         return;
529     }
530
531 #ifdef DO_MESSAGE_BUFFER_PRINT
532     ntries=1;
533     while (ntries) { // try a few times
534         if (pthread_mutex_trylock(&mb_write_lock) == 0) {
535             strncpy(mb_buffers[mb_inbuffer], msg, MB_BUFFERSIZE);
536             mb_inbuffer = MB_NEXT(mb_inbuffer);
537             pthread_cond_signal(&mb_ready_cond);
538             pthread_mutex_unlock(&mb_write_lock);
539             break;
540         } else {
541             nanosleep(&wait, NULL);
542             ntries--;
543         }
544     }
545     if (ntries==0) {  /* lock collision */
546         //         atomic_add(&mb_overruns, 1);
547         // FIXME: atomicity
548         mb_overruns++; // skip the atomicness for now
549     }
550 #else
551     fprintf(stderr,msg);
552 #endif
553 }
554
555 //----------------------------------------
556
557 unsigned char
558 toAscii( unsigned char c )
559 {
560     if ( ( c > 31 ) && ( c < 126) ) {
561         return c;
562     } else {
563         return '.';
564     }
565 }
566
567 /* converts a quadlet to a uchar * buffer
568  * not implemented optimally, but clear
569  */
570 void
571 quadlet2char( quadlet_t quadlet, unsigned char* buff )
572 {
573     *(buff)   = (quadlet>>24)&0xFF;
574     *(buff+1) = (quadlet>>16)&0xFF;
575     *(buff+2) = (quadlet>> 8)&0xFF;
576     *(buff+3) = (quadlet)    &0xFF;
577 }
578
579 void
580 hexDump( unsigned char *data_start, unsigned int length )
581 {
582     unsigned int i=0;
583     unsigned int byte_pos;
584     unsigned int bytes_left;
585
586     if ( length <= 0 ) {
587         return;
588     }
589     if ( length >= 7 ) {
590         for ( i = 0; i < (length-7); i += 8 ) {
591             printf( "%04X: %02X %02X %02X %02X %02X %02X %02X %02X "
592                     "- [%c%c%c%c%c%c%c%c]\n",
593
594                     i,
595
596                     *(data_start+i+0),
597                     *(data_start+i+1),
598                     *(data_start+i+2),
599                     *(data_start+i+3),
600                     *(data_start+i+4),
601                     *(data_start+i+5),
602                     *(data_start+i+6),
603                     *(data_start+i+7),
604
605                     toAscii( *(data_start+i+0) ),
606                     toAscii( *(data_start+i+1) ),
607                     toAscii( *(data_start+i+2) ),
608                     toAscii( *(data_start+i+3) ),
609                     toAscii( *(data_start+i+4) ),
610                     toAscii( *(data_start+i+5) ),
611                     toAscii( *(data_start+i+6) ),
612                     toAscii( *(data_start+i+7) )
613                 );
614         }
615     }
616     byte_pos = i;
617     bytes_left = length - byte_pos;
618
619     printf( "%04X:" ,i );
620     for ( i = byte_pos; i < length; i += 1 ) {
621         printf( " %02X", *(data_start+i) );
622     }
623     for ( i=0; i < 8-bytes_left; i+=1 ) {
624         printf( "   " );
625     }
626
627     printf( " - [" );
628     for ( i = byte_pos; i < length; i += 1) {
629         printf( "%c", toAscii(*(data_start+i)));
630     }
631     for ( i = 0; i < 8-bytes_left; i += 1) {
632         printf( " " );
633     }
634
635     printf( "]" );
636     printf( "\n" );
637 }
638
639 void
640 hexDumpQuadlets( quadlet_t *data, unsigned int length )
641 {
642     unsigned int i=0;
643
644     if ( length <= 0 ) {
645         return;
646     }
647     for (i = 0; i< length; i += 1) {
648         printf( "%02d %04X: %08X (%08X)"
649                 "\n", i, i*4, data[i],ntohl(data[i]));
650     }
651 }
652
653
Note: See TracBrowser for help on using the browser.