[PATCH] Enhance logging in demux_ts, input_dvb and video_out_xv

The three attached patches (against 1.1.6) each increase the amount of
debug logging in their respective components. We've found the extra
logging useful when trying to track down faults.

I've split this into three patches to make it easier to apply only some
of our changes.
--
Comments welcome,

Simon Farnsworth

3 files changed, 70 insertions, 13 deletions

diff --git a/src/demuxers/demux_ts.c b/src/demuxers/demux_ts.c
index aea0c8ca1..c57fc34ef 100644
--- a/src/demuxers/demux_ts.c
+++ b/src/demuxers/demux_ts.c
@@ -683,7 +683,11 @@ static int demux_ts_parse_pes_header (xine_t *xine, demux_ts_media *m,
   stream_id  = p[3];
 
   if (packet_len==0)
+  {
+    xprintf (xine, XINE_VERBOSITY_DEBUG,
+             "demux_ts: error pes length 0\n");
     return 0;
+  }
 
 #ifdef TS_LOG
   printf ("demux_ts: packet stream id: %.2x len: %d (%x)\n",
@@ -1244,7 +1248,7 @@ printf("Program Number is %i, looking for %i\n",program_number,this->program_num
     case ISO_14496_PART10_VIDEO:
       if (this->videoPid == INVALID_PID) {
 #ifdef TS_PMT_LOG
-        printf ("demux_ts: PMT video pid 0x%.4x\n", pid);
+        printf ("demux_ts: PMT video pid 0x%.4x type %2.2x\n", pid, stream[0]);
 #endif
         demux_ts_pes_new(this, this->media_num, pid, this->video_fifo,stream[0]);
 	this->videoMedia = this->media_num;
@@ -1266,7 +1270,7 @@ printf("Program Number is %i, looking for %i\n",program_number,this->program_num
         }
         if(!found) {
 #ifdef TS_PMT_LOG
-            printf ("demux_ts: PMT audio pid 0x%.4x\n", pid);
+            printf ("demux_ts: PMT audio pid 0x%.4x type %2.2x\n", pid, stream[0]);
 #endif
             demux_ts_pes_new(this, this->media_num, pid, this->audio_fifo,stream[0]);
             this->audio_tracks[this->audio_tracks_count].pid = pid;
@@ -1280,7 +1284,7 @@ printf("Program Number is %i, looking for %i\n",program_number,this->program_num
       break;
     case ISO_13818_PRIVATE:
 #ifdef TS_PMT_LOG
-      printf ("demux_ts: PMT streamtype 13818_PRIVATE, pid: 0x%.4x\n", pid);
+      printf ("demux_ts: PMT streamtype 13818_PRIVATE, pid: 0x%.4x type %2.2x\n", pid, stream[0]);
 
       for (i = 5; i < coded_length; i++)
         printf ("%.2x ", stream[i]);
@@ -1289,7 +1293,7 @@ printf("Program Number is %i, looking for %i\n",program_number,this->program_num
       break;
     case  ISO_13818_TYPE_C: /* data carousel */
 #ifdef TS_PMT_LOG
-      printf ("demux_ts: PMT streamtype 13818_TYPE_C, pid: 0x%.4x\n", pid);
+      printf ("demux_ts: PMT streamtype 13818_TYPE_C, pid: 0x%.4x type %2.2x\n", pid, stream[0]);
 #endif
       break;
     case ISO_13818_PES_PRIVATE:
@@ -1305,7 +1309,7 @@ printf("Program Number is %i, looking for %i\n",program_number,this->program_num
 	  }
           if(!found) {
 #ifdef TS_PMT_LOG
-            printf ("demux_ts: PMT AC3 audio pid 0x%.4x\n", pid);
+            printf ("demux_ts: PMT AC3 audio pid 0x%.4x type %2.2x\n", pid, stream[0]);
 #endif
           demux_ts_pes_new(this, this->media_num, pid,
                            this->audio_fifo, 0x81);
@@ -1323,7 +1327,7 @@ printf("Program Number is %i, looking for %i\n",program_number,this->program_num
         else if (stream[i] == 0x56)
           {
 #ifdef TS_PMT_LOG
-            printf ("demux_ts: PMT Teletext, pid: 0x%.4x\n", pid);
+            printf ("demux_ts: PMT Teletext, pid: 0x%.4x type %2.2x\n", pid, stream[0]);
 
             for (i = 5; i < coded_length; i++)
               printf ("%.2x ", stream[i]);
@@ -1358,10 +1362,11 @@ printf("Program Number is %i, looking for %i\n",program_number,this->program_num
 				 pid, this->video_fifo,
 				 stream[0]);
 #ifdef TS_LOG
-		printf("demux_ts: DVBSUB: pid 0x%.4x: %s  page %ld %ld\n",
+		printf("demux_ts: DVBSUB: pid 0x%.4x: %s  page %ld %ld type %2.2x\n",
 		       pid, lang->desc.lang,
 		       lang->desc.comp_page_id,
-		       lang->desc.aux_page_id);
+		       lang->desc.aux_page_id,
+                       stream[0]);
 #endif
 	      }
 	  }
diff --git a/src/input/input_dvb.c b/src/input/input_dvb.c
index 6536af8d8..6cb4be50e 100644
--- a/src/input/input_dvb.c
+++ b/src/input/input_dvb.c
@@ -105,6 +105,7 @@
 #define LOG_VERBOSE
 /*
 #define LOG
+#define LOG_READS
 */
 
 #include "xine_internal.h"
@@ -583,7 +584,8 @@ static tuner_t *tuner_init(xine_t * xine, int adapter)
     this = (tuner_t *) xine_xmalloc(sizeof(tuner_t));
 
     _x_assert(this != NULL);
-    
+
+    xprintf(this->xine, XINE_VERBOSITY_DEBUG, "tuner_init adapter=%d\n", adapter);
     this->fd_frontend = -1;
     for (x = 0; x < MAX_FILTERS; x++)
       this->fd_pidfilter[x] = 0;
@@ -628,7 +630,7 @@ static tuner_t *tuner_init(xine_t * xine, int adapter)
      xprintf(this->xine,XINE_VERBOSITY_DEBUG,"input_dvb: couldn't set EIT to nonblock: %s\n",strerror(errno));
     /* and the internal filter used for PAT & PMT */
    if(fcntl(this->fd_pidfilter[INTERNAL_FILTER], F_SETFL, O_NONBLOCK)<0)
-     xprintf(this->xine,XINE_VERBOSITY_DEBUG,"input_dvb: couldn't set EIT to nonblock: %s\n",strerror(errno));
+     xprintf(this->xine,XINE_VERBOSITY_DEBUG,"input_dvb: couldn't set INTERNAL to nonblock: %s\n",strerror(errno));
     /* and the frontend */
     fcntl(this->fd_frontend, F_SETFL, O_NONBLOCK);
    
@@ -1004,7 +1006,7 @@ static int tuner_tune_it (tuner_t *this, struct dvb_frontend_parameters
   while (ioctl(this->fd_frontend, FE_GET_EVENT, &event) != -1);
 
   if (ioctl(this->fd_frontend, FE_SET_FRONTEND, front_param) <0) {
-    xprintf(this->xine, XINE_VERBOSITY_DEBUG, "setfront front: %s\n", strerror(errno));
+    xprintf(this->xine, XINE_VERBOSITY_DEBUG, "input_dvb: setfront front: %s\n", strerror(errno));
     return 0;
   }
 
@@ -1030,7 +1032,7 @@ static int tuner_tune_it (tuner_t *this, struct dvb_frontend_parameters
   do {
     status = 0;
     if (ioctl(this->fd_frontend, FE_READ_STATUS, &status) < 0) {
-      xprintf(this->xine, XINE_VERBOSITY_DEBUG, "fe get event: %s\n", strerror(errno));
+      xprintf(this->xine, XINE_VERBOSITY_DEBUG, "input_dvb: fe get event: %s\n", strerror(errno));
       return 0;
     }
 
@@ -2470,8 +2472,10 @@ static off_t dvb_plugin_read (input_plugin_t *this_gen,
   if (!this->tuned_in)
       return 0;
   dvb_event_handler (this);
+#ifdef LOG_READS
   xprintf(this->class->xine,XINE_VERBOSITY_DEBUG,
 	  "input_dvb: reading %" PRIdMAX " bytes...\n", (intmax_t)len);
+#endif
 
 #ifndef DVB_NO_BUFFERING
   nbc_check_buffers (this->nbc); 
@@ -2523,9 +2527,11 @@ static off_t dvb_plugin_read (input_plugin_t *this_gen,
 	      break;
 	  } 
 
+#ifdef LOG_READS
       xprintf(this->class->xine,XINE_VERBOSITY_DEBUG,
 	      "input_dvb: got %" PRIdMAX " bytes (%" PRIdMAX "/%" PRIdMAX " bytes read)\n", 
 	      (intmax_t)n, (intmax_t)total, (intmax_t)len);
+#endif
     
       if (n > 0){  
 	  this->curpos += n;
diff --git a/src/video_out/video_out_xv.c b/src/video_out/video_out_xv.c
index dde15fb0f..95a847c2c 100644
--- a/src/video_out/video_out_xv.c
+++ b/src/video_out/video_out_xv.c
@@ -56,6 +56,7 @@
 #include <X11/extensions/XShm.h>
 #include <X11/extensions/Xv.h>
 #include <X11/extensions/Xvlib.h>
+#include <time.h>
 
 #define LOG_MODULE "video_out_xv"
 #define LOG_VERBOSE
@@ -262,7 +263,9 @@ static XvImage *create_ximage (xv_driver_t *this, XShmSegmentInfo *shminfo,
     height = 1;
 
   if (this->use_pitch_alignment) {
+    lprintf ("use_pitch_alignment old width=%d",width);
     width = (width + 7) & ~0x7;
+    lprintf ("use_pitch_alignment new width=%d",width);
   }
 
   switch (format) {
@@ -286,6 +289,7 @@ static XvImage *create_ximage (xv_driver_t *this, XShmSegmentInfo *shminfo,
     gX11Fail = 0;
     x11_InstallXErrorHandler (this);
 
+    lprintf( "XvShmCreateImage format=0x%x, width=%d, height=%d\n", xv_format, width, height );
     image = XvShmCreateImage(this->display, this->xv_port, xv_format, 0,
 			     width, height, shminfo);
 
@@ -297,6 +301,22 @@ static XvImage *create_ximage (xv_driver_t *this, XShmSegmentInfo *shminfo,
       goto finishShmTesting;
     }
 
+    {
+    int q;
+
+    lprintf( "XvImage id %d\n", image->id );
+    lprintf( "XvImage width %d\n", image->width );
+    lprintf( "XvImage height %d\n", image->height );
+    lprintf( "XvImage data_size %d\n", image->data_size );
+    lprintf( "XvImage num_planes %d\n", image->num_planes );
+    
+        for( q=0; q < image->num_planes; q++)
+        {
+            lprintf( "XvImage pitches[%d] %d\n",  q, image->pitches[q] );
+            lprintf( "XvImage offsets[%d] %d\n",  q, image->offsets[q] );
+        }
+    }
+
     shminfo->shmid = shmget(IPC_PRIVATE, image->data_size, IPC_CREAT | 0777);
 
     if (image->data_size==0) {
@@ -750,6 +770,16 @@ static int xv_redraw_needed (vo_driver_t *this_gen) {
   return ret;
 }
 
+/* Used in xv_display_frame to determine how long XvShmPutImage takes
+   - if slower than 60fps, print a message
+*/
+static double timeOfDay()
+{
+    struct timeval t;
+    gettimeofday( &t, NULL );
+    return ((double)t.tv_sec) + (((double)t.tv_usec)/1000000.0);
+}
+
 static void xv_display_frame (vo_driver_t *this_gen, vo_frame_t *frame_gen) {
   xv_driver_t  *this  = (xv_driver_t *) this_gen;
   xv_frame_t   *frame = (xv_frame_t *) frame_gen;
@@ -793,9 +823,14 @@ static void xv_display_frame (vo_driver_t *this_gen, vo_frame_t *frame_gen) {
    * ask for offset and output size
    */
   xv_redraw_needed (this_gen);
+  {
+  double start_time;
+  double end_time;
+  double elapse_time;
+  int factor;
 
   LOCK_DISPLAY(this);
-
+  start_time = timeOfDay();
   if (this->use_shm) {
     XvShmPutImage(this->display, this->xv_port,
                   this->drawable, this->gc, this->cur_frame->image,
@@ -814,9 +849,20 @@ static void xv_display_frame (vo_driver_t *this_gen, vo_frame_t *frame_gen) {
   }
 
   XSync(this->display, False);
+  end_time = timeOfDay();
 
   UNLOCK_DISPLAY(this);
 
+  elapse_time = end_time - start_time;
+  factor = (int)(elapse_time/(1.0/60.0));
+
+  if( factor > 1 )
+  {
+    lprintf( "%s PutImage %dX interval (%fs)\n",
+        log_line_prefix(), factor, elapse_time );
+  }
+  }
+
   /*
   printf ("video_out_xv: xv_display_frame... done\n");
   */