Add debug messages

Use VDPAU_TRACE=1 environment variable to print the messages.

6 files changed, 115 insertions, 4 deletions

diff --git a/src/presentation_queue.c b/src/presentation_queue.c
index d995257..7be7183 100644
--- a/src/presentation_queue.c
+++ b/src/presentation_queue.c
@@ -42,6 +42,12 @@ static void pqt_display_surface_to_idle_state(tegra_pqt *pqt)
         surf->status = VDP_PRESENTATION_QUEUE_STATUS_IDLE;
         pthread_cond_signal(&surf->idle_cond);
         pqt->disp_surf = NULL;
+
+        DebugMsg("visible surface %u became idle\n",
+                 surf->surface_id);
+    } else {
+        DebugMsg("trying to set invisible surface %u to idle\n",
+                 surf->surface_id);
     }
     pthread_mutex_unlock(&surf->lock);
 
@@ -53,6 +59,9 @@ static void pqt_display_surface(tegra_pqt *pqt, tegra_surface *surf)
     tegra_device *dev = pqt->dev;
     CARD64 count;
 
+    DebugMsg("surface %u earliest_presentation_time %llu+\n",
+             surf->surface_id, surf->earliest_presentation_time);
+
     if (!DRI_OUTPUT) {
         if (surf->set_bg && surf->bg_color != pqt->bg_color) {
             XSetWindowBackground(dev->display, pqt->drawable, surf->bg_color);
@@ -62,6 +71,8 @@ static void pqt_display_surface(tegra_pqt *pqt, tegra_surface *surf)
         }
 
         if (surf->shared) {
+            DebugMsg("surface %u YUV overlay\n", surf->surface_id);
+
             XvPutImage(dev->display, dev->xv_port,
                        pqt->drawable, pqt->gc,
                        surf->shared->xv_img,
@@ -74,6 +85,8 @@ static void pqt_display_surface(tegra_pqt *pqt, tegra_surface *surf)
                        surf->shared->dst_width,
                        surf->shared->dst_height);
         } else if (surf->xv_img) {
+            DebugMsg("surface %u RGB overlay\n", surf->surface_id);
+
             XvPutImage(dev->display, dev->xv_port,
                        pqt->drawable, pqt->gc,
                        surf->xv_img,
@@ -89,6 +102,8 @@ static void pqt_display_surface(tegra_pqt *pqt, tegra_surface *surf)
 
         XSync(dev->display, 0);
     } else if (pqt->dri_pixbuf) {
+        DebugMsg("surface %u DRI\n", surf->surface_id);
+
         DRI2SwapBuffers(dev->display, pqt->drawable, 0, 0, 0, &count);
     }
 
@@ -101,6 +116,8 @@ static void pqt_display_surface(tegra_pqt *pqt, tegra_surface *surf)
         pqt->disp_surf = surf;
     }
     pthread_mutex_unlock(&surf->lock);
+
+    DebugMsg("surface %u-\n", surf->surface_id);
 }
 
 static void pqt_update_dri_buffer(tegra_pqt *pqt, tegra_surface *surf)
@@ -118,10 +135,14 @@ static void pqt_update_dri_buffer(tegra_pqt *pqt, tegra_surface *surf)
         return;
     }
 
+    DebugMsg("surface %u+\n", surf->surface_id);
+
     pthread_mutex_lock(&surf->lock);
     pthread_mutex_lock(&pqt->dev->lock);
 
     if (surf->shared) {
+        DebugMsg("surface %u transfer YUV\n", surf->surface_id);
+
         if (surf->set_bg) {
             host1x_gr2d_clear_rect_clipped(surf->dev->stream,
                                            pqt->dri_pixbuf,
@@ -150,6 +171,8 @@ static void pqt_update_dri_buffer(tegra_pqt *pqt, tegra_surface *surf)
                                  surf->shared->dst_width,
                                  surf->shared->dst_height);
     } else if (surf->pixbuf) {
+        DebugMsg("surface %u transfer RGB\n", surf->surface_id);
+
         host1x_gr2d_surface_blit(pqt->dev->stream,
                                  surf->pixbuf,
                                  pqt->dri_pixbuf,
@@ -166,6 +189,8 @@ static void pqt_update_dri_buffer(tegra_pqt *pqt, tegra_surface *surf)
 
     pthread_mutex_unlock(&pqt->dev->lock);
     pthread_mutex_unlock(&surf->lock);
+
+    DebugMsg("surface %u-\n", surf->surface_id);
 }
 
 static void * presentation_queue_thr(void *opaque)
@@ -227,11 +252,12 @@ static void * presentation_queue_thr(void *opaque)
                 continue;
             }
 
-            if (surf->earliest_presentation_time < earliest_time) {
-                earliest_time = surf->earliest_presentation_time;
-            }
-
             if (surf->earliest_presentation_time > time) {
+                if (surf->earliest_presentation_time < earliest_time) {
+                    DebugMsg("surface %u in queue\n", surf->surface_id);
+                    earliest_time = surf->earliest_presentation_time;
+                }
+
                 pthread_mutex_unlock(&surf->lock);
                 continue;
             }
@@ -244,6 +270,12 @@ static void * presentation_queue_thr(void *opaque)
         }
 
         time = earliest_time;
+
+        if (time != UINT64_MAX) {
+            DebugMsg("next wake on %llu\n", time);
+        } else {
+            DebugMsg("going to sleep.. zZZ\n");
+        }
     }
 
     pthread_mutex_unlock(&pq->lock);
@@ -458,6 +490,9 @@ VdpStatus vdp_presentation_queue_display(
     pthread_mutex_lock(&surf->lock);
 
     if (surf->status == VDP_PRESENTATION_QUEUE_STATUS_QUEUED) {
+        ErrorMsg("trying to re-queue surface %u %llu %llu\n",
+                 surf->surface_id, surf->earliest_presentation_time,
+                 earliest_presentation_time);
         ret = VDP_STATUS_ERROR;
         goto unlock_surf;
     }
@@ -477,6 +512,9 @@ VdpStatus vdp_presentation_queue_display(
         goto unlock_surf;
     }
 
+    DebugMsg("queue surface %u %llu\n",
+             surf->surface_id, surf->earliest_presentation_time);
+
     surf->status = VDP_PRESENTATION_QUEUE_STATUS_QUEUED;
     surf->earliest_presentation_time = earliest_presentation_time;
 
@@ -537,7 +575,13 @@ retry:
     pthread_mutex_unlock(&pq->lock);
 
     if (ret == VDP_STATUS_OK) {
+        DebugMsg("block on surface %u+ %llu\n",
+                 surf->surface_id, surf->earliest_presentation_time);
+
         pthread_cond_wait(&surf->idle_cond, &surf->lock);
+
+        DebugMsg("block on surface %u-\n", surf->surface_id);
+
         *first_presentation_time = surf->first_presentation_time;
     } else {
         *first_presentation_time = 0;
diff --git a/src/presentation_queue_target.c b/src/presentation_queue_target.c
index 86b2725..03bec38 100644
--- a/src/presentation_queue_target.c
+++ b/src/presentation_queue_target.c
@@ -41,6 +41,8 @@ void pqt_update_dri_pixbuf(tegra_pqt *pqt)
         return;
     }
 
+    DebugMsg("width %d height %d\n", width, height);
+
     err = drm_tegra_bo_from_name(&bo, dev->drm, buf[0].names[0], 0);
     if (err) {
         return;
diff --git a/src/surface.c b/src/surface.c
index 32798b4..44e5c8f 100644
--- a/src/surface.c
+++ b/src/surface.c
@@ -42,7 +42,12 @@ int dynamic_alloc_surface_data(tegra_surface *surf)
 
     pthread_mutex_lock(&surf->lock);
     if (!surf->data_allocated) {
+        DebugMsg("surface %u %p\n", surf->surface_id, surf);
+
         ret = alloc_surface_data(surf);
+    } else {
+        DebugMsg("surface %u %p.. already allocated\n",
+                 surf->surface_id, surf);
     }
     pthread_mutex_unlock(&surf->lock);
 
@@ -55,7 +60,12 @@ int dynamic_release_surface_data(tegra_surface *surf)
 
     pthread_mutex_lock(&surf->lock);
     if (surf->data_allocated) {
+        DebugMsg("surface %u %p\n", surf->surface_id, surf);
+
         ret = release_surface_data(surf);
+    } else {
+        DebugMsg("surface %u %p.. already released\n",
+                 surf->surface_id, surf);
     }
     surf->data_dirty = false;
     pthread_mutex_unlock(&surf->lock);
@@ -428,6 +438,7 @@ uint32_t create_surface(tegra_device *dev,
 
     if (surface_id != VDP_INVALID_HANDLE) {
         surf->surface_id = surface_id;
+        DebugMsg("surface %u %p\n", surface_id, surf);
     } else {
         destroy_surface(surf);
     }
@@ -446,6 +457,8 @@ VdpStatus unref_surface(tegra_surface *surf)
         return VDP_STATUS_OK;
     }
 
+    DebugMsg("surface %u %p\n", surf->surface_id, surf);
+
     dynamic_release_surface_data(surf);
     unref_device(surf->dev);
 
@@ -458,6 +471,8 @@ VdpStatus unref_surface(tegra_surface *surf)
 
 VdpStatus destroy_surface(tegra_surface *surf)
 {
+    DebugMsg("surface %u %p\n", surf->surface_id, surf);
+
     pthread_mutex_lock(&surf->lock);
     if (surf->flags & SURFACE_OUTPUT) {
         shared_surface_kill_disp(surf);
diff --git a/src/surface_shared.c b/src/surface_shared.c
index c63487f..d8e0dce 100644
--- a/src/surface_shared.c
+++ b/src/surface_shared.c
@@ -140,6 +140,9 @@ tegra_shared_surface *create_shared_surface(tegra_surface *disp,
     pthread_mutex_unlock(&video->lock);
     pthread_mutex_unlock(&shared_lock);
 
+    DebugMsg("%p disp %u video %u\n",
+             shared, disp->surface_id, video->surface_id);
+
     return shared;
 }
 
@@ -154,6 +157,11 @@ void unref_shared_surface(tegra_shared_surface *shared)
         return;
     }
 
+    DebugMsg("%p disp %u video %u\n",
+             shared,
+             shared->disp->surface_id,
+             shared->video->surface_id);
+
     unref_surface(shared->video);
     unref_surface(shared->disp);
 
@@ -164,6 +172,11 @@ void unref_shared_surface(tegra_shared_surface *shared)
 
 static void shared_surface_break_link_locked(tegra_shared_surface *shared)
 {
+    DebugMsg("%p disp %u video %u\n",
+             shared,
+             shared->disp->surface_id,
+             shared->video->surface_id);
+
     shared->disp->shared = NULL;
     shared->video->shared = NULL;
 }
@@ -179,6 +192,11 @@ tegra_surface * shared_surface_swap_video(tegra_surface *old)
     shared = old->shared;
     if (shared) {
         ref_surface(old);
+
+        DebugMsg("%p disp %u video %u\n",
+                 shared,
+                 shared->disp->surface_id,
+                 shared->video->surface_id);
     }
     pthread_mutex_unlock(&shared_lock);
 
@@ -236,6 +254,11 @@ int shared_surface_transfer_video(tegra_surface *disp)
 
     pthread_mutex_lock(&disp->dev->lock);
 
+    DebugMsg("%p disp %u video %u\n",
+             shared,
+             shared->disp->surface_id,
+             shared->video->surface_id);
+
     if (disp->set_bg) {
         host1x_gr2d_clear_rect_clipped(disp->dev->stream,
                                        disp->pixbuf,
@@ -291,6 +314,11 @@ void shared_surface_kill_disp(tegra_surface *disp)
 
     shared = disp->shared;
     if (shared) {
+        DebugMsg("%p disp %u video %u\n",
+                shared,
+                shared->disp->surface_id,
+                shared->video->surface_id);
+
         shared_surface_break_link_locked(shared);
     }
 
diff --git a/src/vdpau_tegra.c b/src/vdpau_tegra.c
index 5fa11b4..e5441e6 100644
--- a/src/vdpau_tegra.c
+++ b/src/vdpau_tegra.c
@@ -21,6 +21,8 @@
 
 pthread_mutex_t global_lock = PTHREAD_MUTEX_INITIALIZER;
 
+bool tegra_vdpau_debug;
+
 static tegra_device  * tegra_devices[MAX_DEVICES_NB];
 static tegra_decoder * tegra_decoders[MAX_DECODERS_NB];
 static tegra_mixer   * tegra_mixers[MAX_MIXERS_NB];
@@ -195,6 +197,9 @@ void replace_surface(tegra_surface *old_surf, tegra_surface *new_surf)
         new_surf->surface_id = old_surf->surface_id;
         old_surf->surface_id = MAX_SURFACES_NB;
 
+        DebugMsg("surface %u %p -> %p\n",
+                 new_surf->surface_id, new_surf, old_surf);
+
         tegra_surfaces[new_surf->surface_id] = new_surf;
     }
 }
@@ -505,6 +510,8 @@ VdpStatus unref_device(tegra_device *dev)
     if (!atomic_dec_and_test(&dev->refcnt))
         return VDP_STATUS_OK;
 
+    DebugMsg("device closed\n");
+
     XvUngrabPort(dev->display, dev->xv_port, CurrentTime);
     tegra_stream_destroy(dev->stream);
     drm_tegra_channel_close(dev->gr2d);
@@ -543,6 +550,7 @@ EXPORTED VdpStatus vdp_imp_device_create_x11(Display *display,
     XvImageFormatValues *fmt;
     VdpDevice i;
     drm_magic_t magic;
+    char *debug_str;
     unsigned int ver, rel, req, ev, err;
     unsigned int num_adaptors;
     int num_formats;
@@ -550,6 +558,11 @@ EXPORTED VdpStatus vdp_imp_device_create_x11(Display *display,
     int drm_fd = -1;
     int ret;
 
+    debug_str = getenv("VDPAU_TEGRA_DEBUG");
+    if (debug_str && strcmp(debug_str, "0")) {
+        tegra_vdpau_debug = true;
+    }
+
     drm_fd = drmOpen("tegra", NULL);
     if (drm_fd < 0) {
         perror("Failed to open tegra DRM\n");
diff --git a/src/vdpau_tegra.h b/src/vdpau_tegra.h
index 90e41d7..0bedf10 100644
--- a/src/vdpau_tegra.h
+++ b/src/vdpau_tegra.h
@@ -102,6 +102,13 @@
     fprintf(stderr, "%s:%d/%s(): " fmt, \
             __FILE__, __LINE__, __func__, ##args)
 
+#define DebugMsg(fmt, args...) \
+do { \
+    if (tegra_vdpau_debug) \
+        fprintf(stderr, "%s:%d/%s(): " fmt, \
+                __FILE__, __LINE__, __func__, ##args); \
+} while (0)
+
 #define CLAMP(_v, _vmin, _vmax) \
     (((_v) < (_vmin) ? (_vmin) : (((_v) > (_vmax)) ? (_vmax) : (_v))))
 
@@ -109,6 +116,8 @@
 
 #define DRI_OUTPUT      0
 
+extern bool tegra_vdpau_debug;
+
 extern VdpCSCMatrix CSC_BT_601;
 extern VdpCSCMatrix CSC_BT_709;