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

Revision 691, 17.8 kB (checked in by ppalmers, 15 years ago)

- fix RT safety

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