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

Revision 671, 16.9 kB (checked in by ppalmers, 15 years ago)

- make the backlog actually do what it is supposed to do
- make the backlog thread safe

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