From 84133d2fad4c392de75d41d88a19850734ea5523 Mon Sep 17 00:00:00 2001 From: Simon Farnsworth Date: Wed, 2 May 2007 17:23:48 +0100 Subject: [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 --- src/demuxers/demux_ts.c | 21 +++++++++++-------- src/input/input_dvb.c | 14 +++++++++---- src/video_out/video_out_xv.c | 48 +++++++++++++++++++++++++++++++++++++++++++- 3 files changed, 70 insertions(+), 13 deletions(-) (limited to 'src') 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 #include #include +#include #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"); */ -- cgit v1.2.3