Ich habe in VDR eine Messung eingebaut wie lange read() braucht wenn es vom VDR section handler aufgerufen wird. Wenn read() länger als eine Sekunde braucht, wird ein Eintrag in syslog geschrieben:
Code
int cDevice::ReadFilter(int Handle, void *Buffer, size_t Length)
{
std::chrono::time_point<std::chrono::high_resolution_clock> begin = std::chrono::high_resolution_clock::now();
int ret_code = safe_read(Handle, Buffer, Length);
std::chrono::duration<double> timeNeeded = std::chrono::high_resolution_clock::now() - begin;
if (timeNeeded.count() > 1) esyslog("cDevice::ReadFilter, Handle %d, time needed %g seconds", Handle, timeNeeded.count());
return ret_code;
}
Die Meldung im syslog wird geschrieben, nachdem read() fertig ist.
Code
2025-10-27T21:17:37.618124+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 128,255 seconds
bedeutet also, dass read() von 21:15:29.36 bis 21:17:37.62 gebraucht hat.
Ergebnis vom 27.10: In der Zeit von 20:34:07 bis 21:31:17 gab es sehr viele solcher Einträge. Außerhalb dieser Zeit gab es keine solche Einträge im syslog. Im syslog sieht das dann so aus:
Code
2025-10-27T20:34:07.500655+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 13,5704 seconds
2025-10-27T20:34:20.055517+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 12,5547 seconds
2025-10-27T20:34:32.910427+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 12,8546 seconds
2025-10-27T20:35:01.317756+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 28,4068 seconds
2025-10-27T20:35:12.352129+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 11,0339 seconds
2025-10-27T20:35:23.264645+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 10,9121 seconds
2025-10-27T20:35:48.155840+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 24,8913 seconds
2025-10-27T20:35:51.149727+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 2,99367 seconds
2025-10-27T20:36:10.313709+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 19,163 seconds
2025-10-27T20:36:10.313975+01:00 rpi4s vdr: [2666984] tp 211387 (3842/FF) read incomplete section - len = 4098, r = 4096
2025-10-27T20:36:21.250134+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 10,9363 seconds
2025-10-27T20:36:29.688050+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 8,43774 seconds
2025-10-27T20:36:40.712332+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 11,0232 seconds
2025-10-27T20:36:48.230051+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 7,51758 seconds
2025-10-27T20:36:58.726923+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 10,4971 seconds
2025-10-27T20:37:11.662921+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 12,9354 seconds
2025-10-27T20:37:21.603390+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 9,9403 seconds
2025-10-27T20:37:31.398860+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 9,79517 seconds
2025-10-27T20:37:57.507324+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 26,1082 seconds
2025-10-27T20:37:57.513527+01:00 rpi4s vdr: [2666984] tp 211387 (3842/FF) read incomplete section - len = 4098, r = 4096
2025-10-27T20:38:17.405602+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 19,8979 seconds
2025-10-27T20:38:36.906447+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 19,5007 seconds
2025-10-27T20:38:56.882467+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 19,864 seconds
2025-10-27T20:39:41.256717+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 44,374 seconds
2025-10-27T20:40:49.646352+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 68,369 seconds
2025-10-27T20:41:18.940739+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 28,7598 seconds
2025-10-27T20:41:23.288979+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 4,34788 seconds
2025-10-27T20:42:03.319504+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 40,0302 seconds
2025-10-27T20:42:26.943011+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 23,6231 seconds
2025-10-27T20:42:34.257120+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 7,31404 seconds
2025-10-27T20:42:40.740320+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 6,48303 seconds
2025-10-27T20:42:46.885812+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 6,1446 seconds
2025-10-27T20:42:57.990940+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 10,5222 seconds
2025-10-27T20:43:05.338839+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 7,3475 seconds
2025-10-27T20:43:10.001670+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 4,14561 seconds
2025-10-27T20:43:21.718029+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 11,7158 seconds
2025-10-27T20:43:33.844869+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 12,1263 seconds
2025-10-27T20:43:53.179121+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 19,3341 seconds
2025-10-27T20:44:03.719431+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 10,5403 seconds
2025-10-27T20:44:09.581343+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 5,86043 seconds
2025-10-27T20:44:22.279971+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 12,698 seconds
2025-10-27T20:44:32.900639+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 10,6202 seconds
2025-10-27T20:44:48.478194+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 15,5777 seconds
2025-10-27T20:44:56.913424+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 8,4347 seconds
2025-10-27T20:44:59.203934+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 2,29039 seconds
2025-10-27T20:45:09.128027+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 9,92396 seconds
2025-10-27T20:45:26.394003+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 17,2654 seconds
2025-10-27T20:45:46.381306+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 19,9867 seconds
2025-10-27T20:45:56.456867+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 10,0756 seconds
2025-10-27T20:46:05.920092+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 9,46305 seconds
... (messages skipped)
2025-10-27T21:06:56.269718+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 81,4303 seconds
... (messages skipped)
2025-10-27T21:17:37.618124+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 128,255 seconds
... (messages skipped)
2025-10-27T21:30:57.675428+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 37,5355 seconds
2025-10-27T21:31:17.518029+01:00 rpi4s vdr: [2666984] cDevice::ReadFilter, Handle 36, time needed 19,8415 seconds
Display More
Ein Auszug aus der mediasrv.log in diesem Zeitraum ist attached. Die mediasrv.log sieht übrigens immer so aus, auch wenn read() kurze Antwortzeiten hat.
Sundtek , könnt ihr Euch das bitte mal anschauen.