[Spice-devel,04/12] qxl-wddm-dod: Debug warning on long wait on event

Submitted by Yuri Benditovich on March 12, 2017, 8:45 a.m.

Details

Message ID 1489308309-9728-5-git-send-email-yuri.benditovich@daynix.com
State New
Headers show
Series "Set of patches for further support of VSync" ( rev: 1 ) in Spice

Not browsing as part of any series.

Commit Message

Yuri Benditovich March 12, 2017, 8:45 a.m.
In release build this does not affect the code.
In debug build we will have a warning printout when waiting
on event is close to 2 seconds - this can be a cause of following
stop by OS. The printout contains name of related event variable.
There is one event (in offload thread) that long wait on it
does not affect any functionality, for it this warning is disabled.

Signed-off-by: Yuri Benditovich <yuri.benditovich@daynix.com>
---
 qxldod/QxlDod.cpp |  3 ++-
 qxldod/QxlDod.h   | 15 +++++++++++++--
 2 files changed, 15 insertions(+), 3 deletions(-)

Patch hide | download patch | download mbox

diff --git a/qxldod/QxlDod.cpp b/qxldod/QxlDod.cpp
index 01de9b3..7e3afb3 100755
--- a/qxldod/QxlDod.cpp
+++ b/qxldod/QxlDod.cpp
@@ -5095,7 +5095,8 @@  void QxlDevice::PresentThreadRoutine()
         // No need for a mutex, only one consumer thread
         SPICE_RING_CONS_WAIT(m_PresentRing, wait);
         while (wait) {
-            WaitForObject(&m_PresentEvent, NULL);
+            // we do not want indication of long wait on this event
+            DoWaitForObject(&m_PresentEvent, NULL, NULL);
             SPICE_RING_CONS_WAIT(m_PresentRing, wait);
         }
         drawables = *SPICE_RING_CONS_ITEM(m_PresentRing);
diff --git a/qxldod/QxlDod.h b/qxldod/QxlDod.h
index 324b940..7bb5de5 100755
--- a/qxldod/QxlDod.h
+++ b/qxldod/QxlDod.h
@@ -416,11 +416,13 @@  struct Resource {
 
 BOOLEAN
 FORCEINLINE
-WaitForObject(
+DoWaitForObject(
     PVOID Object,
-    PLARGE_INTEGER Timeout)
+    PLARGE_INTEGER Timeout,
+    LPCSTR name)
 {
     NTSTATUS status;
+    TimeMeasurement tm;
     status = KeWaitForSingleObject (
             Object,
             Executive,
@@ -428,9 +430,18 @@  WaitForObject(
             FALSE,
             Timeout);
     ASSERT(NT_SUCCESS(status));
+    tm.Stop();
+    if (name && tm.Diff() > 1900)
+    {
+        // 2 seconds in PresentDisplayOnly triggers watchdog on Win10RS1
+        // when VSync control enabled. Print the exact event name.
+        DbgPrint(TRACE_LEVEL_ERROR, ("Waiting %d ms for %s\n", tm.Diff(), name));
+    }
     return (status == STATUS_SUCCESS);
 }
 
+#define WaitForObject(o, timeout) DoWaitForObject((o), (timeout), #o)
+
 VOID
 FORCEINLINE
 ReleaseMutex(

Comments

> 
> In release build this does not affect the code.
> In debug build we will have a warning printout when waiting
> on event is close to 2 seconds - this can be a cause of following
> stop by OS. The printout contains name of related event variable.
> There is one event (in offload thread) that long wait on it
> does not affect any functionality, for it this warning is disabled.
> 
> Signed-off-by: Yuri Benditovich <yuri.benditovich@daynix.com>
> ---
>  qxldod/QxlDod.cpp |  3 ++-
>  qxldod/QxlDod.h   | 15 +++++++++++++--
>  2 files changed, 15 insertions(+), 3 deletions(-)
> 
> diff --git a/qxldod/QxlDod.cpp b/qxldod/QxlDod.cpp
> index 01de9b3..7e3afb3 100755
> --- a/qxldod/QxlDod.cpp
> +++ b/qxldod/QxlDod.cpp
> @@ -5095,7 +5095,8 @@ void QxlDevice::PresentThreadRoutine()
>          // No need for a mutex, only one consumer thread
>          SPICE_RING_CONS_WAIT(m_PresentRing, wait);
>          while (wait) {
> -            WaitForObject(&m_PresentEvent, NULL);
> +            // we do not want indication of long wait on this event
> +            DoWaitForObject(&m_PresentEvent, NULL, NULL);
>              SPICE_RING_CONS_WAIT(m_PresentRing, wait);
>          }
>          drawables = *SPICE_RING_CONS_ITEM(m_PresentRing);
> diff --git a/qxldod/QxlDod.h b/qxldod/QxlDod.h
> index 324b940..7bb5de5 100755
> --- a/qxldod/QxlDod.h
> +++ b/qxldod/QxlDod.h
> @@ -416,11 +416,13 @@ struct Resource {
>  
>  BOOLEAN
>  FORCEINLINE
> -WaitForObject(
> +DoWaitForObject(
>      PVOID Object,
> -    PLARGE_INTEGER Timeout)
> +    PLARGE_INTEGER Timeout,
> +    LPCSTR name)
>  {
>      NTSTATUS status;
> +    TimeMeasurement tm;
>      status = KeWaitForSingleObject (
>              Object,
>              Executive,
> @@ -428,9 +430,18 @@ WaitForObject(
>              FALSE,
>              Timeout);
>      ASSERT(NT_SUCCESS(status));
> +    tm.Stop();
> +    if (name && tm.Diff() > 1900)
> +    {
> +        // 2 seconds in PresentDisplayOnly triggers watchdog on Win10RS1
> +        // when VSync control enabled. Print the exact event name.
> +        DbgPrint(TRACE_LEVEL_ERROR, ("Waiting %d ms for %s\n", tm.Diff(),
> name));
> +    }
>      return (status == STATUS_SUCCESS);
>  }
>  
> +#define WaitForObject(o, timeout) DoWaitForObject((o), (timeout), #o)
> +
>  VOID
>  FORCEINLINE
>  ReleaseMutex(

This patch looks good.
Which timers did you discovered having the wait issue?

Frediano
On Tue, Mar 21, 2017 at 2:05 PM, Frediano Ziglio <fziglio@redhat.com> wrote:

> >
> > In release build this does not affect the code.
> > In debug build we will have a warning printout when waiting
> > on event is close to 2 seconds - this can be a cause of following
> > stop by OS. The printout contains name of related event variable.
> > There is one event (in offload thread) that long wait on it
> > does not affect any functionality, for it this warning is disabled.
> >
> > Signed-off-by: Yuri Benditovich <yuri.benditovich@daynix.com>
> > ---
> >  qxldod/QxlDod.cpp |  3 ++-
> >  qxldod/QxlDod.h   | 15 +++++++++++++--
> >  2 files changed, 15 insertions(+), 3 deletions(-)
> >
> > diff --git a/qxldod/QxlDod.cpp b/qxldod/QxlDod.cpp
> > index 01de9b3..7e3afb3 100755
> > --- a/qxldod/QxlDod.cpp
> > +++ b/qxldod/QxlDod.cpp
> > @@ -5095,7 +5095,8 @@ void QxlDevice::PresentThreadRoutine()
> >          // No need for a mutex, only one consumer thread
> >          SPICE_RING_CONS_WAIT(m_PresentRing, wait);
> >          while (wait) {
> > -            WaitForObject(&m_PresentEvent, NULL);
> > +            // we do not want indication of long wait on this event
> > +            DoWaitForObject(&m_PresentEvent, NULL, NULL);
> >              SPICE_RING_CONS_WAIT(m_PresentRing, wait);
> >          }
> >          drawables = *SPICE_RING_CONS_ITEM(m_PresentRing);
> > diff --git a/qxldod/QxlDod.h b/qxldod/QxlDod.h
> > index 324b940..7bb5de5 100755
> > --- a/qxldod/QxlDod.h
> > +++ b/qxldod/QxlDod.h
> > @@ -416,11 +416,13 @@ struct Resource {
> >
> >  BOOLEAN
> >  FORCEINLINE
> > -WaitForObject(
> > +DoWaitForObject(
> >      PVOID Object,
> > -    PLARGE_INTEGER Timeout)
> > +    PLARGE_INTEGER Timeout,
> > +    LPCSTR name)
> >  {
> >      NTSTATUS status;
> > +    TimeMeasurement tm;
> >      status = KeWaitForSingleObject (
> >              Object,
> >              Executive,
> > @@ -428,9 +430,18 @@ WaitForObject(
> >              FALSE,
> >              Timeout);
> >      ASSERT(NT_SUCCESS(status));
> > +    tm.Stop();
> > +    if (name && tm.Diff() > 1900)
> > +    {
> > +        // 2 seconds in PresentDisplayOnly triggers watchdog on Win10RS1
> > +        // when VSync control enabled. Print the exact event name.
> > +        DbgPrint(TRACE_LEVEL_ERROR, ("Waiting %d ms for %s\n",
> tm.Diff(),
> > name));
> > +    }
> >      return (status == STATUS_SUCCESS);
> >  }
> >
> > +#define WaitForObject(o, timeout) DoWaitForObject((o), (timeout), #o)
> > +
> >  VOID
> >  FORCEINLINE
> >  ReleaseMutex(
>
> This patch looks good.
> Which timers did you discovered having the wait issue?
>
> Depends where the problematic flow is - first one is DisplayEvent, then -
MemLock



> Frediano
>