How long should a playback take to start

[Edster]

How long should a playback take to start ?

I have just installed for the first time. 
Live TV works great.  1-2 seconds to start then channel flips are almost instant.
If I start a recording it takes about 60 seconds to start.  50 seconds with the menu frozen on the option I just picked then about 10 seconds of black screen and then it starts.  I can jump back and forward fine and it works great.  If I stop it and restart another 60 seconds or so to get going again.

I have an old wired MVP box.  It is wried on 10/100 MB network.  The cable is fine as the MVP box is replacing a pc and that would start the playback in about 3-4 seconds.
The VDR server is an old enough pc A P-III 800 MHz (or so).
I am using vomp 0.3.0-8 on both the server and the MVP.  I also tried 0.3.0 (same)
The server does have SOftdevice  on it outputting to DirectFB on an i810 VGA board.  Would this impact it ?

Why would this be far slower than live TV ?  Have I got a bad seting ?

I'm not complaining - It is a great product.  I'm just checking that its not just a bad setting on my side and everypone else is running far faster 

[MartenR]

Play with the TCP window size. (60 seconds is too long).

Marten

[Edster]

What sort of time do you get (or anyone else for that matter).  Should I be looking for 30 seconds or 5 seconds ?
I turned off softdevice last night and that didn't seem to make much difference.
I'll have a play with TCP window size today.

[Chris]

Edster: Mine starts playback in just over 1s. Granted, I have a faster server than you, but all it's doing in this case is file serving - network latency and disk performance would be far more important than the cpu speed. Can you post a vomp client log from the point where you press ok or play on a recording up to it starting to play. (Done by telnetting into your mvp, run killall vompclient, run vompclient -d and paste back the relevant bit).

[Edster]

Sorry in advance for the loooooooong post :

I have got it to about 30 seconds by messing with tcp window values and making sure nothing else is slowing down 'server'

Code Select Expand


18:22:30.776152 [debug]  854 Remote - Button 37
18:22:30.777114 [debug]  854 TBBoxx - Draw
18:22:30.846347 [debug]  854 Boxx - Construct, now 7
18:22:30.893740 [debug]  854 Boxx - Destruct, now 6
18:22:30.894421 [debug]  854 BoxStack - Locked for update
18:22:30.975275 [debug]  854 BoxStack - Unlocked for update
18:22:31.654836 [debug]  854 Remote - Button 37
18:22:31.655539 [debug]  854 VRecordingList - Found the option you pointed at. 24 /video/24/24/2009-02-14.22.58.30.99.rec
18:22:31.656125 [debug]  854 Boxx - Construct, now 7
18:22:31.657092 [debug]  854 Boxx - Construct, now 8
18:22:31.664685 [debug]  854 TBBoxx - Draw
18:22:31.692158 [debug]  854 BoxStack - Locked for add
18:22:31.692839 [debug]  854 BoxStack - Unlocked for add
18:22:31.693336 [debug]  854 BoxStack - Locked for update
18:22:31.702829 [debug]  854 BoxStack - Unlocked for update
18:22:32.524543 [debug]  854 Remote - Button 37
18:22:32.525269 [debug]  854 BoxStack - Locked for remove
18:22:32.535553 [debug]  854 BoxStack - Unlocked for remove
18:22:32.536237 [debug]  854 BoxStack - remove: going to delete boxx 0x1023ec20, num 3
18:22:32.536788 [debug]  854 Boxx - Destruct, now 7
18:22:32.538576 [debug]  854 Boxx - Destruct, now 6
18:22:32.539330 [debug]  854 Command - processing message 3
18:22:32.539829 [debug]  854 Command - Sending message to boxstack
18:22:32.540312 [debug]  854 BoxStack - sending message from box 0x1023ec20 to box 0x1023e468 3
18:22:32.541452 [debug]  854 VRecordingList - Got message value 3
18:22:32.542180 [debug]  854 VDR - RR sleep - opcode 20
18:22:36.028317 [debug]  861 VDR - Sending KA packet
18:22:36.030552 [debug]  861 VDR - Rxd correct KA reply
18:22:39.089335 [debug]  861 VDR - Rxd a response packet, requestID=26, len=268
18:22:39.090208 [debug]  854 VDR - RR unsleep
18:22:39.090814 [debug]  854 RecInfo - timerStart 0
18:22:39.091549 [debug]  854 RecInfo - timerEnd 0
18:22:39.092341 [debug]  854 RecInfo - resumePoint 13645
18:22:39.092840 [debug]  854 RecInfo - Summary: Day 7: 2.00pm to 3.00pm. Day seven of the real-time drama. After the President refuses to withdraw he
18:22:39.093630 [debug]  854 RecInfo - numComponents: 1
18:22:39.094451 [debug]  854 RecInfo - streams[0]: 2
18:22:39.094950 [debug]  854 RecInfo - types[0]: 3
18:22:39.095433 [debug]  854 RecInfo - languages[0]: eng
18:22:39.096478 [debug]  854 RecInfo - descriptions[0]:
18:22:39.097001 [debug]  854 Recording - Recording has loaded recInfo 0x1023f070
18:22:39.098047 [debug]  854 VDR - RR sleep - opcode 21
18:22:43.088320 [debug]  861 VDR - Sending KA packet
18:22:43.089595 [debug]  861 VDR - Rxd correct KA reply
18:22:45.772188 [debug]  861 VDR - Rxd a response packet, requestID=27, len=4
18:22:45.773056 [debug]  854 VDR - RR unsleep
18:22:45.773793 [debug]  854 VDR - RR sleep - opcode 9
18:22:49.768321 [debug]  861 VDR - Sending KA packet
18:22:49.769625 [debug]  861 VDR - Rxd correct KA reply
18:22:52.151197 [debug]  861 VDR - Rxd a response packet, requestID=28, len=12
18:22:52.152201 [debug]  854 VDR - RR unsleep
18:22:52.152893 [debug]  854 VDR - VDR said length is: 1129361484 95907
18:22:52.155325 [debug]  854 VDR - RR sleep - opcode 7
18:22:52.183789 [debug]  861 VDR - Rxd a response packet, requestID=29, len=10000
18:22:52.184685 [debug]  854 VDR - RR unsleep
18:22:52.185738 [debug]  854 VDR - RR sleep - opcode 8
18:22:52.193962 [debug]  861 VDR - Rxd a response packet, requestID=30, len=4
18:22:52.194822 [debug]  854 VDR - RR unsleep
18:22:52.195352 [debug]  854 Recording - Recording has messed about and worked out radio = 0
18:22:52.196155 [debug]  854 Boxx - Construct, now 7
18:22:52.196965 [debug]  854 Boxx - Construct, now 8
18:22:52.197846 [debug]  854 Demuxer - Reset called
18:22:52.198993 [debug]  854 Demuxer - Flush called
18:22:52.267681 [debug]  854 VDR - RR sleep - opcode 12
18:22:52.269813 [debug]  861 VDR - Rxd a response packet, requestID=31, len=2
18:22:52.270673 [debug]  854 VDR - RR unsleep
18:22:52.271405 [debug]  854 VDR - RR sleep - opcode 12
18:22:52.272729 [debug]  861 VDR - Rxd a response packet, requestID=32, len=2
18:22:52.273705 [debug]  854 VDR - RR unsleep
18:22:52.274497 [debug]  854 VVideoRec - SM: 120 EM: 120
18:22:52.336353 [debug]  854 VDR - RR sleep - opcode 12
18:22:52.338508 [debug]  861 VDR - Rxd a response packet, requestID=33, len=3
18:22:52.339369 [debug]  854 VDR - RR unsleep
18:22:52.340220 [debug]  854 VVideoRec - Do WSS: 0
18:22:52.400891 [debug]  854 BoxStack - Locked for add
18:22:52.401705 [debug]  854 BoxStack - Unlocked for add
18:22:52.402370 [debug]  854 BoxStack - Locked for update
18:22:52.500956 [debug]  854 BoxStack - Unlocked for update
18:22:52.501683 [debug]  854 VVideoRec - Starting stream: /video/24/24/2009-02-14.22.58.30.99.rec at frame: 0
18:22:52.502436 [debug]  854 VDR - RR sleep - opcode 9
18:22:56.338320 [debug]  861 VDR - Sending KA packet
18:22:56.339731 [debug]  861 VDR - Rxd correct KA reply
18:22:58.692408 [debug]  861 VDR - Rxd a response packet, requestID=34, len=12
18:22:58.693402 [debug]  854 VDR - RR unsleep
18:22:58.694087 [debug]  854 VDR - VDR said length is: 1129361484 95907
18:22:58.694622 [debug]  854 Player - Player has received length bytes of 1129361484
18:22:58.695377 [debug]  854 Player - Player has received length frames of 95907
18:22:58.695910 [debug]  854 Player - LOCKED
18:22:58.696385 [debug]  854 Player - Switch state from 6 to 1
18:22:58.701304 [debug]  854 Audio - doMuting: user=0 sys=0
18:22:58.702125 [debug]  854 Audio - MUTE OFF OFF OFF
18:22:58.702806 [debug]  854 Audio - doMuting: user=0 sys=0
18:22:58.703330 [debug]  854 Audio - MUTE OFF OFF OFF
18:22:58.708363 [debug]  854 Demuxer - Reset called
18:22:58.709043 [debug]  854 Demuxer - Flush called
18:22:58.709554 [debug]  854 Demuxer - setFrameNum 0
18:22:58.711087 [debug]  862 VDR - RR sleep - opcode 16
18:22:58.711993 [debug]  854 Player - Immediate play
18:22:58.713035 [debug]  861 VDR - Rxd a response packet, requestID=35, len=8
18:22:58.713853 [debug]  862 VDR - RR unsleep
18:22:58.714654 [debug]  862 VDR - VDR said new position is: 0
18:22:58.715181 [debug]  862 Player - startFeedPlay: wantedframe 0 goto 0
18:22:58.716448 [debug]  862 VDR - RR sleep - opcode 7
18:22:58.718187 [debug]  864 VFeed - Started
18:22:58.719828 [debug]  865 SUBTITLES - Sleeping until nudged.
18:22:58.836093 [debug]  854 Boxx - Construct, now 9
18:22:58.838758 [debug]  854 VVideoRec - Draw bar clocks
18:22:58.842618 [debug]  854 VVideoRec -      0:00:00 / 1:03:56
18:22:58.851448 [debug]  854 BoxStack - Locked for update
18:22:58.863392 [debug]  854 BoxStack - Unlocked for update
18:22:58.864081 [debug]  854 Timers - Starting cancel timer 0x1023f22c 1, list size = 1
18:22:58.864624 [debug]  854 Timers - Starting set timer 1
18:22:58.867070 [debug]  854 Timers - Timer set for 0x1023f22c ref 1
18:22:58.869447 [debug]  854 Timers - Second rollover - CHECK FIXME
18:22:58.869930 [debug]  854 Timers - Starting set timer 1
18:22:58.874194 [debug]  854 Timers - Timer set for 0x1023f22c ref 2
18:22:58.874749 [debug]  854 Boxx - Destruct, now 8
18:22:58.931447 [debug]  861 VDR - Rxd a response packet, requestID=36, len=250000
18:22:58.932359 [debug]  862 VDR - RR unsleep
18:22:58.933044 [debug]  862 Player - Startup Audio stream chosen c0
18:22:58.934232 [debug]  862 Demux - Aspect ratio difference signalled
18:22:58.934771 [debug]  862 Demuxer - Entering audio sync: Video PTS = 2570825455
18:22:58.935821 [debug]  862 Demuxer - Entering audio sync: Audio PTS = 0
18:22:58.936373 [debug]  862 Demuxer - +* PTS INIT *+ 2570825455 0
18:22:58.967410 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.034675 [debug]  861 VDR - Rxd a response packet, requestID=37, len=100000
18:22:59.035587 [debug]  862 VDR - RR unsleep
18:22:59.039218 [debug]  862 Demuxer - Leaving  audio sync: Audio PTS = 2570828180
18:22:59.049243 [debug]  862 Demux - Aspect ratio difference signalled
18:22:59.050801 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.122345 [debug]  856 Timers - Timer firing for client 0x1023f22c ref 2
18:22:59.124131 [debug]  866 Timers - sending timer to 0x1023f22c with parameter 2
18:22:59.126362 [debug]  866 VVideoRec - Draw bar clocks
18:22:59.136868 [debug]  866 BoxStack - Locked for update
18:22:59.149529 [debug]  866 BoxStack - Unlocked for update
18:22:59.150238 [debug]  866 Timers - Starting set timer 1
18:22:59.150756 [debug]  866 Timers - timerEventFinished for 0x1023f22c
18:22:59.152891 [debug]  866 Timers - timerEventFinished RESTART for 0x1023f22c
18:22:59.169873 [debug]  864 VFeed - Released
18:22:59.188520 [debug]  863 Player - UNLOCKING
18:22:59.191660 [debug]  861 VDR - Rxd a response packet, requestID=38, len=100000
18:22:59.192554 [debug]  862 VDR - RR unsleep
18:22:59.205981 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.283223 [debug]  861 VDR - Rxd a response packet, requestID=39, len=100000
18:22:59.284125 [debug]  862 VDR - RR unsleep
18:22:59.297543 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.348232 [debug]  861 VDR - Rxd a response packet, requestID=40, len=100000
18:22:59.349309 [debug]  862 VDR - RR unsleep
18:22:59.358440 [debug]  856 Timers - Timer firing for client 0x1023f22c ref 2
18:22:59.363998 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.372350 [debug]  867 Timers - sending timer to 0x1023f22c with parameter 2
18:22:59.373067 [debug]  867 VVideoRec - Draw bar clocks
18:22:59.377560 [debug]  867 BoxStack - Locked for update
18:22:59.389641 [debug]  867 BoxStack - Unlocked for update
18:22:59.390337 [debug]  867 Timers - Starting set timer 1
18:22:59.391095 [debug]  867 Timers - timerEventFinished for 0x1023f22c
18:22:59.391628 [debug]  867 Timers - timerEventFinished RESTART for 0x1023f22c
18:22:59.436027 [debug]  861 VDR - Rxd a response packet, requestID=41, len=100000
18:22:59.437077 [debug]  862 VDR - RR unsleep
18:22:59.439631 [debug]  862 Demux - Aspect ratio difference signalled
18:22:59.458973 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.531812 [debug]  861 VDR - Rxd a response packet, requestID=42, len=100000
18:22:59.532858 [debug]  862 VDR - RR unsleep
18:22:59.553241 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.598357 [debug]  856 Timers - Timer firing for client 0x1023f22c ref 2
18:22:59.600992 [debug]  868 Timers - sending timer to 0x1023f22c with parameter 2
18:22:59.601711 [debug]  868 VVideoRec - Draw bar clocks
18:22:59.615113 [debug]  868 VVideoRec -      0:00:00 / 1:03:56
18:22:59.622174 [debug]  868 BoxStack - Locked for update
18:22:59.635507 [debug]  861 VDR - Rxd a response packet, requestID=43, len=100000
18:22:59.636448 [debug]  862 VDR - RR unsleep
18:22:59.655101 [debug]  868 BoxStack - Unlocked for update
18:22:59.655809 [debug]  868 Timers - Starting set timer 1
18:22:59.656325 [debug]  868 Timers - timerEventFinished for 0x1023f22c
18:22:59.656823 [debug]  868 Timers - timerEventFinished RESTART for 0x1023f22c
18:22:59.658266 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.726822 [debug]  861 VDR - Rxd a response packet, requestID=44, len=100000
18:22:59.727862 [debug]  862 VDR - RR unsleep
18:22:59.741398 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.790564 [debug]  861 VDR - Rxd a response packet, requestID=45, len=100000
18:22:59.791613 [debug]  862 VDR - RR unsleep
18:22:59.804800 [debug]  862 VDR - RR sleep - opcode 7
18:22:59.858378 [debug]  856 Timers - Timer firing for client 0x1023f22c ref 2
18:22:59.861640 [debug]  869 Timers - sending timer to 0x1023f22c with parameter 2
18:22:59.862368 [debug]  869 VVideoRec - Draw bar clocks
18:22:59.867635 [debug]  869 VVideoRec -      0:00:00 / 1:03:56
18:22:59.875777 [debug]  869 BoxStack - Locked for update
18:22:59.877467 [debug]  861 VDR - Rxd a response packet, requestID=46, len=100000
18:22:59.904789 [debug]  862 VDR - RR unsleep
18:22:59.907761 [debug]  862 Demux - Aspect ratio difference signalled
18:22:59.908533 [debug]  862 Player - Callback from demuxer
18:22:59.909259 [debug]  862 VDR - RR sleep - opcode 12
18:22:59.910210 [debug]  869 BoxStack - Unlocked for update
18:22:59.910794 [debug]  861 VDR - Rxd a response packet, requestID=47, len=4
18:22:59.912132 [debug]  862 VDR - RR unsleep
18:22:59.913234 [debug]  862 Player - Demuxer is forced to 16:9, ignoring aspect switching
18:22:59.913762 [debug]  862 Video - Setting aspect to 1
18:22:59.914681 [debug]  862 Command - PMFOS called
18:22:59.915453 [notice] 854 Core - Signal 23 received
18:22:59.915731 [debug]  854 Core - SIGURG caught
18:22:59.915981 [debug]  854 Command - processing message 22
18:22:59.916210 [debug]  854 Command - Sending message to boxstack
18:22:59.916573 [debug]  854 BoxStack - sending message from box 0x1023ef60 to box 0x1023f1e8 22
18:22:59.916854 [debug]  854 VVideoRec - Message received
18:22:59.929241 [debug]  869 Timers - Second rollover - CHECK FIXME
18:22:59.929925 [debug]  869 Timers - Starting set timer 1
18:22:59.930737 [debug]  869 Timers - timerEventFinished for 0x1023f22c
18:22:59.931510 [debug]  869 Timers - timerEventFinished RESTART for 0x1023f22c
18:22:59.928202 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.008688 [debug]  856 Timers - Timer firing for client 0x1023e10c ref 1
18:23:00.010960 [debug]  861 VDR - Rxd a response packet, requestID=48, len=100000
18:23:00.011930 [debug]  862 VDR - RR unsleep
18:23:00.029520 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.030288 [debug]  870 Timers - sending timer to 0x1023e10c with parameter 1
18:23:00.031963 [debug]  870 Timers - Starting set timer 1
18:23:00.032876 [debug]  870 BoxStack - Locked for update
18:23:00.033711 [debug]  870 BoxStack - Unlocked for update
18:23:00.034535 [debug]  870 Timers - timerEventFinished for 0x1023e10c
18:23:00.035052 [debug]  870 Timers - timerEventFinished RESTART for 0x1023e10c
18:23:00.061132 [debug]  861 VDR - Sending KA packet
18:23:00.108944 [debug]  861 VDR - Rxd a response packet, requestID=49, len=100000
18:23:00.109471 [debug]  861 VDR - Rxd correct KA reply
18:23:00.110246 [debug]  862 VDR - RR unsleep
18:23:00.123623 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.139022 [debug]  856 Timers - Timer firing for client 0x1023f22c ref 2
18:23:00.141148 [debug]  871 Timers - sending timer to 0x1023f22c with parameter 2
18:23:00.143417 [debug]  871 VVideoRec - Draw bar clocks
18:23:00.148674 [debug]  871 VVideoRec -      0:00:00 / 1:03:56
18:23:00.156880 [debug]  871 BoxStack - Locked for update
18:23:00.187472 [debug]  871 BoxStack - Unlocked for update
18:23:00.188181 [debug]  871 Timers - Starting set timer 1
18:23:00.190430 [debug]  871 Timers - timerEventFinished for 0x1023f22c
18:23:00.192613 [debug]  871 Timers - timerEventFinished RESTART for 0x1023f22c
18:23:00.199153 [debug]  861 VDR - Rxd a response packet, requestID=50, len=100000
18:23:00.200176 [debug]  862 VDR - RR unsleep
18:23:00.221305 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.300089 [debug]  861 VDR - Rxd a response packet, requestID=51, len=100000
18:23:00.300985 [debug]  862 VDR - RR unsleep
18:23:00.314514 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.386597 [debug]  861 VDR - Rxd a response packet, requestID=52, len=100000
18:23:00.387504 [debug]  862 VDR - RR unsleep
18:23:00.398374 [debug]  856 Timers - Timer firing for client 0x1023f22c ref 2
18:23:00.399562 [debug]  872 Timers - sending timer to 0x1023f22c with parameter 2
18:23:00.400419 [debug]  872 VVideoRec - Draw bar clocks
18:23:00.404615 [debug]  872 VVideoRec -      0:00:01 / 1:03:56
18:23:00.412197 [debug]  872 BoxStack - Locked for update
18:23:00.423968 [debug]  872 BoxStack - Unlocked for update
18:23:00.424806 [debug]  872 Timers - Starting set timer 1
18:23:00.425494 [debug]  872 Timers - timerEventFinished for 0x1023f22c
18:23:00.426011 [debug]  872 Timers - timerEventFinished RESTART for 0x1023f22c
18:23:00.434365 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.508883 [debug]  861 VDR - Rxd a response packet, requestID=53, len=100000
18:23:00.509784 [debug]  862 VDR - RR unsleep
18:23:00.523038 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.575866 [debug]  861 VDR - Rxd a response packet, requestID=54, len=100000
18:23:00.576914 [debug]  862 VDR - RR unsleep
18:23:00.590276 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.628492 [debug]  856 Timers - Timer firing for client 0x1023f22c ref 2
18:23:00.630245 [debug]  873 Timers - sending timer to 0x1023f22c with parameter 2
18:23:00.630553 [debug]  873 VVideoRec - Draw bar clocks
18:23:00.633438 [debug]  873 VVideoRec -      0:00:01 / 1:03:56
18:23:00.636283 [debug]  873 BoxStack - Locked for update
18:23:00.657099 [debug]  873 BoxStack - Unlocked for update
18:23:00.657370 [debug]  873 Timers - Starting set timer 1
18:23:00.659184 [debug]  873 Timers - timerEventFinished for 0x1023f22c
18:23:00.659891 [debug]  873 Timers - timerEventFinished RESTART for 0x1023f22c
18:23:00.696388 [debug]  861 VDR - Rxd a response packet, requestID=55, len=100000
18:23:00.697325 [debug]  862 VDR - RR unsleep
18:23:00.711011 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.790752 [debug]  861 VDR - Rxd a response packet, requestID=56, len=100000
18:23:00.791655 [debug]  862 VDR - RR unsleep
18:23:00.803713 [debug]  854 Remote - Button 31
18:23:00.804013 [debug]  854 VVideoRec - Pre stopPlay
18:23:00.804244 [debug]  854 Timers - Starting cancel timer 0x1023f22c 2, list size = 3
18:23:00.804509 [debug]  854 Timers - Removed timer for 0x1023f22c ref 2
18:23:00.821505 [debug]  854 BoxStack - Locked for update
18:23:00.833404 [debug]  854 BoxStack - Unlocked for update
18:23:00.834096 [debug]  854 VVideoRec - 1
18:23:00.834597 [debug]  854 Player - LOCKED
18:23:00.835077 [debug]  854 Player - Stop called lock
18:23:00.836125 [debug]  854 Player - Switch state from 1 to 6
18:23:00.838501 [debug]  862 VDR - RR sleep - opcode 7
18:23:00.906298 [debug]  861 VDR - Rxd a response packet, requestID=57, len=100000
18:23:00.907195 [debug]  862 VDR - RR unsleep
18:23:01.188343 [debug]  854 Demuxer - Reset called
18:23:01.189050 [debug]  854 Demuxer - Flush called
18:23:01.190057 [debug]  854 Player - UNLOCKING
18:23:01.191122 [debug]  854 VVideoRec - 2
18:23:01.191818 [debug]  854 VDR - RR sleep - opcode 8
18:23:01.198937 [debug]  861 VDR - Rxd a response packet, requestID=58, len=4
18:23:01.199817 [debug]  854 VDR - RR unsleep
18:23:01.200358 [debug]  854 VVideoRec - 3
18:23:01.201378 [debug]  854 Player - Switch state from 6 to 6
18:23:01.203592 [debug]  854 VVideoRec - Post stopPlay
18:23:01.204316 [debug]  854 BoxStack - Locked for remove
18:23:01.204823 [debug]  854 Timers - Starting cancel timer 0x1023f22c 1, list size = 2
18:23:01.205606 [debug]  854 Timers - Removed timer for 0x1023f22c ref 1
18:23:01.206639 [debug]  854 Timers - Starting cancel timer 0x1023f22c 2, list size = 1
18:23:01.298799 [debug]  854 BoxStack - Unlocked for remove
18:23:01.299612 [debug]  854 BoxStack - remove: going to delete boxx 0x1023f1e8, num 3
18:23:01.300305 [debug]  854 VVideoRec - Entering vvideorec destructor
18:23:01.300812 [debug]  854 Video - Setting aspect to 1
18:23:01.301600 [CRAZY]  854 RecInfo - Deleting recinfo: 1, Day 7: 2.00pm to 3.00pm. Day seven of the real-time drama. After the President refuses to
18:23:01.302511 [CRAZY]  854 RecInfo - i: 0, languages[i]=0x1023f1c8:eng
18:23:01.303019 [CRAZY]  854 RecInfo - i: 0, descripti[i]=0x1023f1d8:
18:23:01.303794 [debug]  854 Boxx - Destruct, now 7
18:23:01.305411 [debug]  854 Boxx - Destruct, now 6
18:23:01.762912 [debug]  854 Remote - Button 31



[Edster]

Update :
The server box I am testing on is quite old.  I loaded the vomp on my main box which is a P4 about 1GHz.
I left both online and gave them names so I could pick on MVP bootup.
They both access the recordings off a shared drive on a tiny NAS server so same files same data etc.
The time went from about 25 seconds on the older test box to about 15 seconds on the production box
so I guess that is part of the answer.  I need a new machine