Im Anschluss an VDPAU und die "Hänger" bei HD. Wie ist der aktuelle Stand? möchte ich das Thema der Hänger bei Wiedergabe von H264 codierten Sendern mit vdpau aufgreifen. Gerade beim Einsatz von neueren Distris mit xorg-servern ab 1.9 ist dies relevant, da diese nvidia Treiber ab 256 erfordern, während der letzte gute nvidia Treiber der 195.30 ist.
Beschreibung der Hänger: VDPAU und die "Hänger" bei HD. Wie ist der aktuelle Stand? „Die "Hänger" beginnen mit einem kurzen Standbild (1-2 Sekunden) das dann direkt in einen schnellen Bildvorlauf übergeht, der ebenfalls noch mal 1-2 Sekunden läuft. Der Ton läuft währenddessen ganz normal weiter. Es gibt weder vor noch nach einem Hänger Asynchronitäten. Auf der Konsole erfolgt währendessen die berühmt-berüchtigte Ausgabe "verwerfe Bild mit PTS...". Während dieser Phase kommt es auch zu einer erhöhten CPU-Auslastung (bei einem meiner Rechner dreht der CPU-Lüfter dann hörbar schneller).“
Bei schnelleren Cpus gibt es aber keinen schnellen Bildvorlauf, sondern nur das 1-2 Sekunden lange Standbild, danach läuft der Film normal weiter. Denn schnelle Cpus holen die Verspätung praktisch sofort wieder auf, während langsamere Cpus dazu etwas Zeit brauchen, und während des Aufholens eine Art schnellen Bildvorlauf produzieren.
Um diese Hänger messbar zu machen, gibt es von Durchflieger bzw. von rnissl den Profiling bzw. Watchdog Patch. Ich habe die Patche so verändert, dass sie zwecks dauerhaftem mitloggen ins syslog schreiben. Dabei habe ich mich über die unterschiedlichen Ergebnisse gewundert.
Bei 720p Sendern gibt es alle 20ms ein Bild. Der watchdog patch lässt öfters mal eins oder mehrere aus. Hier fehlt 10.915:
Sep 3 22:32:10 vdr xine: ==== 22:32:10.835 WATCHDOG 0 ms: vdp_decoder_render took 0.000 ms to execute ====
Sep 3 22:32:10 vdr xine: ==== 22:32:10.855 WATCHDOG 0 ms: vdp_decoder_render took 0.000 ms to execute ====
Sep 3 22:32:10 vdr xine: ==== 22:32:10.875 WATCHDOG 0 ms: vdp_decoder_render took 0.035 ms to execute ====
Sep 3 22:32:10 vdr xine: ==== 22:32:10.895 WATCHDOG 0 ms: vdp_decoder_render took 0.000 ms to execute ====
Sep 3 22:32:10 vdr xine: ==== 22:32:10.935 WATCHDOG 0 ms: vdp_decoder_render took 0.000 ms to execute ====
Sep 3 22:32:10 vdr xine: ==== 22:32:10.955 WATCHDOG 0 ms: vdp_decoder_render took 0.045 ms to execute ====
Hier fehlen mehrere watchdog ausgaben, und die zweite Zeit ist Null im Gegensatz zur Profiling Ausgabe. Aktiviert war das innere und äußere profiling, sowie der watchdog.
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1452) inner_diff: 0,042 ms
Nov 3 16:06:26 vdr xine: ==== 16:06:26.760 WATCHDOG 0,0000000000000000000000000000000 ms: vdp_decoder_render took 0,105 ms to execute ====
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1460) outer_diff: 0,251 ms
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1452) inner_diff: 0,040 ms
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1460) outer_diff: 0,115 ms
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1452) inner_diff: 0,038 ms
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1460) outer_diff: 0,113 ms
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1452) inner_diff: 0,064 ms
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1460) outer_diff: 0,137 ms
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1452) inner_diff: 0,047 ms
Nov 3 16:06:26 vdr xine: ==== 16:06:26.840 WATCHDOG 0,0000000000000000000000000000000 ms: vdp_decoder_render took 0,000 ms to execute ====
Nov 3 16:06:26 vdr xine: vdpau_h264: (decode_render:1460) outer_diff: 0,236 ms
Display More
Hier die syslog Einträge eines Hängers. Obwohl sowohl der Profiling als auch der Watchdog im Einsatz waren, hat nur der Profiling Patch Alarm gegeben. Der Watchdog patch hat beim Hänger keinen output verursacht:
Nov 5 01:58:36 vdr xine: ==== 01:58:36.669 WATCHDOG 0,250 ms: vdp_decoder_render took 1,098 ms to execute ====
Nov 5 01:59:32 vdr xine: ==== 01:59:32.051 WATCHDOG 0,250 ms: vdp_decoder_render took 1,084 ms to execute ====
Nov 5 01:59:53 vdr xine: ==== 01:59:53.292 WATCHDOG 0,250 ms: vdp_decoder_render took 0,531 ms to execute ====
Nov 5 03:19:09 vdr xine: ==== 03:19:09.332 VDPAU PROFILE O_PEAK 262,500 ms ==== render
Nov 5 16:59:16 vdr xine: ==== 16:59:16.658 VDPAU PROFILE O_PEAK 39,595 ms ==== render
Nov 5 16:59:18 vdr xine: ==== 16:59:18.536 VDPAU PROFILE O_PEAK 1877,478 ms ==== render
Nov 5 16:59:20 vdr xine: ==== 16:59:20.401 VDPAU PROFILE O_PEAK 1864,526 ms ==== render
Nov 5 17:12:20 vdr xine: ==== 17:12:20.641 WATCHDOG 0,250 ms: vdp_decoder_render took 1,169 ms to execute ====
Nov 5 17:15:39 vdr xine: ==== 17:15:39.620 WATCHDOG 0,250 ms: vdp_decoder_render took 1,089 ms to execute ====
Nov 5 17:15:52 vdr xine: ==== 17:15:52.471 WATCHDOG 0,250 ms: vdp_decoder_render took 1,346 ms to execute ====
Syslog oder printf´s macht dabei keinen Unterschied.
1. Frage: Wieso sind die Ergebnisse vom Profiling patch und watchdog patch so unterschiedlich?
Jetzt das Merkwürdigste. Wenn ich nur den watchdog patch verwende, gibt es auf meinem System keine Hänger mehr! Ich habe lange gezögert, das hier zu schreiben, aber nach einigen Monaten glaube ich nicht mehr an Zufall. Auf meinem System bekomme ich nach mehrmaligem Wechsel der patche eindeutig mit dem Profiling patch (egal ob watchdog patch dabei oder nicht) Hänger, wenn aber nur der watchdog patch drauf ist keine Hänger. Und damit meine ich nicht nur die syslog Einträge, ich sehe auch keine Hänger.
2. Frage: Bei wem ist das auch so, bzw. bei wem ist das nicht so? Und welches System ist im Einsatz (Gpu, nvidia Treiber, Cpu, Software)?
Gpu: G210, nvidia Treiber: 290.x, Cpu: Sempron 140@Athlon II X2, opensuse 11.3 mit aktuellem Kernel und xine cvs.
Die Aufnahmen waren von den ÖRs in 720p H264.
Falls das nicht nur bei mir so ist, müsste man eventuell die Theorie, dass der nvidia Treiber Schuld ist, ändern, und den Fehler auch in xine suchen.
Nachtrag zur Abgrenzung von anderen Rucklern und Hängern
Der Grund für die Hänger sind laut durchflieger und rnissl ein Problem im nvidia treiber, welches sich dadurch zeigt, dass vdpau decoder Aufrufe zu viel Laufzeit für ein frame benötigen. Dies tritt auch bei Aufnahmen auf.
Es wäre aufschlussreich, wenn ihr die syslog Ausgaben um den Zeitpunkt des Hängers herum postet. Zur Kontrolle, ob der watchdog funktioniert, kann man mit "grep -e render messages" schauen, ob überhaupt Ausgaben kommen (bei 3ms sollte ab und zu was erscheinen).
Anbei der Patch, auf dem gerade nur der watchdog aktiv ist. Man kann aber auch das innere oder äußere Profiling aktivieren. Der Patch hat sich im Lauf der Zeit bei mir verändert, obige Ausgaben sind teils mit Vorgänger Versionen entstanden und beim watchdog hatte ich mal ms von int auf double geändert.
--- alterh264_decode.c.orig 2011-10-20 16:53:49.664963952 +0200
+++ alterh264_decode.c 2011-11-05 17:16:54.174458001 +0100
@@ -1305,6 +1305,9 @@
}
+#include <syslog.h>
+#include "xine/watchdog.h"
+static watchdog_t wd;
static void decode_render( vdpau_h264_alter_decoder_t *vd, int bad_frame )
{
@@ -1429,7 +1432,40 @@
vbits[(i*2)+1].bitstream = seq->buf + seq->slices[i].buf_offset;
vbits[(i*2)+1].bitstream_bytes = seq->slices[i].len;
}
+
+// struct timeval start_tv_o, end_tv_o, diff_tv_o;
+// xine_monotonic_clock(&start_tv_o, NULL);
+
+ init_watchdog(&wd, "vdp_decoder_render", 0);
+//static int n = 0;
+ start_watchdog(&wd, 3.250);
+
+// struct timeval start_tv, end_tv, diff_tv;
+// xine_monotonic_clock(&start_tv, NULL);
+
st = accel->vdp_decoder_render( vd->decoder, accel->surface, (VdpPictureInfo*)&info, seq->slices_count * 2, vbits );
+
+// xine_monotonic_clock(&end_tv, NULL);
+// timersub(&end_tv, &start_tv, &diff_tv);
+// uint64_t diff_us = diff_tv.tv_sec * 1000000 + diff_tv.tv_usec;
+// if (diff_us >= 35000) {
+// syslog(LOG_DEBUG, "%s: (%s:%d) inner_diff: %.3lf ms\n", LOG_MODULE, __XINE_FUNCTION__, __LINE__, ((double)diff_us)/1000.0);}
+
+ stop_watchdog(&wd);
+
+// struct timeval now;
+// gettimeofday(&now, 0);
+// struct tm lt;
+// localtime_r(&now.tv_sec, <);
+// xine_monotonic_clock(&end_tv_o, NULL);
+// timersub(&end_tv_o, &start_tv_o, &diff_tv_o);
+// uint64_t diff_us_o = diff_tv_o.tv_sec * 1000000 + diff_tv_o.tv_usec;
+// if (diff_us_o >= 35000) {
+//// syslog(LOG_DEBUG, "%s: (%s:%d) outer_peak: %.3lf ms\n", LOG_MODULE, __XINE_FUNCTION__, __LINE__, ((double)diff_us_o)/1000.0);}
+// syslog(LOG_DEBUG, "==== %02d:%02d:%02d.%03ld VDPAU PROFILE O_PEAK %.3lf ms ==== render\n", lt.tm_hour, lt.tm_min, lt.tm_sec, now.tv_usec / 1000, ((double)diff_us_o)/1000.0);}
+
+//n++; if (wd.wd_fired) syslog(LOG_DEBUG, "call %d\n", n);
+
if ( st != VDP_STATUS_OK )
lprintf( "**********************DECODING failed! - surface = %d - %s\n", accel->surface, accel->vdp_get_error_string( st ) );
else
Display More
Edit:
Teil3: Rezept gegen Mikroruckler bei vdpau h264 mit xine *