Peculiar AVI problems

[UKGuest44]

Hi,

I'm trying to play some XVID avi files on my MVP with the latest version of GBPVR.

I always record the programs in mpeg, edit out the adverts, then convert to xvid.

All of my avi's play fine, with the exception of one series, and I cannot understand why?

The avi's start to play, go in between 10 seconds and about 40 seconds, and then returns to the menu. As this doesnt happen with the others, I'm trying to work out what is causing this behavior.

I dont think it's a problem with trans2mp, as if I pause it before it returns to the menu, trans2mvp happily keeps transcoding and the file grows fine.

I dont think it's a problem with the output file, because if I pause it and allow trans2mvp to keep transcoding to it's temporary file - make a copy of the file before it's deleted, and then try to play it directly, the MVP plays it no problems past the points it normally exits out on.

As far as I can understand, for no reason, it decides to stop playing the perfectly fine and perfectly generated transcode mpg, and I cant seem to find out why

I've tried to include some logs in case it helps

Trans2mvp log:

Code:

16:31:43.515 INFO Log started 16:31:43.515 VERBOSE Will try to use ffdshow... 16:31:43.515 INFO TRANSCODING: H:\MYVIDE~1\VICARO~1\THEVIC~1.AVI 16:31:43.515 INFO TARGET: H:\My Videos\Need Converting\MVP000DFE001B62.mpg 16:31:43.515 INFO ... 16:31:43.531 INFO T1 16:31:43.562 INFO T2. 16:31:43.625 INFO T3 16:31:43.625 INFO T4 16:31:43.625 INFO T4.1 16:31:43.625 INFO T4.2 16:31:43.625 INFO T5 16:31:43.625 INFO T6 16:31:43.625 VERBOSE AVI file type. 16:31:43.625 VERBOSE FOURCC: XVID 16:31:43.703 VERBOSE ConnectPins: 'Output' to 'input pin' 16:31:43.765 VERBOSE @1 16:31:43.843 VERBOSE @2 16:31:43.843 VERBOSE @3 16:31:43.843 VERBOSE @4 16:31:43.843 VERBOSE Connecting Stream 00 to encoder's Input Video 16:31:43.843 VERBOSE ConnectPins: 'Stream 00' to 'Input Video' 16:31:43.875 VERBOSE Connecting Stream 01 to encoder's Input Audio 16:31:43.875 VERBOSE ConnectPins: 'Stream 01' to 'Input Audio' 16:31:43.875 VERBOSE About to list graph filters 16:31:43.875 INFO Graph contains the following filters: 16:31:43.890 INFO - ffdshow raw video filter 16:31:43.890 INFO - MainConcept (Hauppauge) MPEG Encoder 16:31:43.890 INFO - ffdshow Audio Decoder 16:31:43.890 INFO - ffdshow MPEG-4 Video Decoder 16:31:43.890 INFO - AVI Splitter 16:31:43.890 INFO - H:\MYVIDE~1\VICARO~1\THEVIC~1.AVI 16:31:43.984 VERBOSE About to start graph 16:31:44.015 VERBOSE transcode processing started

And the GBPVR log:

Code:

26/08/2005 16:31:43.046 INFO [2] playFile() 26/08/2005 16:31:43.234 VERBOSE [2] About to play file: H:\My Videos\Vicar of Dibley\The Vicar of Dibley - Arrival.AVI 26/08/2005 16:31:43.234 VERBOSE [2] Sending MVP Video Playback Request: H:\My Videos\Vicar of Dibley\The Vicar of Dibley - Arrival.AVI 26/08/2005 16:31:43.234 VERBOSE [2] Playback started: H:\My Videos\Vicar of Dibley\The Vicar of Dibley - Arrival.AVI 26/08/2005 16:31:43.296 VERBOSE [886] MVP playback requested: H:\MYVIDE~1\VICARO~1\THEVIC~1.AVI 26/08/2005 16:31:43.296 VERBOSE [886] getValue() loading new key/value into cache: /settings/RecordingsDirectory 26/08/2005 16:31:43.296 VERBOSE [886] getValue: /settings/RecordingsDirectory : H:\My Videos\Need Converting 26/08/2005 16:31:43.296 VERBOSE [886] getValue() loading new key/value into cache: /settings/MVPTranscodeUseFFDSHOW 26/08/2005 16:31:43.296 VERBOSE [886] getValue: /settings/MVPTranscodeUseFFDSHOW : true 26/08/2005 16:31:43.296 VERBOSE [885] MVP data read: 1 (7) 26/08/2005 16:31:43.328 VERBOSE [885] MVP request processed 26/08/2005 16:31:43.343 VERBOSE [2] Checking if resume prompt needs to be shown 26/08/2005 16:31:43.343 VERBOSE [2] PlaybackPositionManager.getLastPlaybackPosition(H:\My Videos\Vicar of Dibley\The Vicar of Dibley - Arrival.AVI) 26/08/2005 16:31:43.343 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin0 26/08/2005 16:31:43.343 VERBOSE [2] getValue: /settings/VideoPlugin0 : TV Guide 26/08/2005 16:31:43.343 VERBOSE [2] GuideMenuTask created 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin1 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin1 : 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin2 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin2 : 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin3 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin3 : 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin4 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin4 : 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin5 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin5 : 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin6 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin6 : 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin7 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin7 : 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin8 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin8 : 26/08/2005 16:31:43.375 VERBOSE [2] getValue() loading new key/value into cache: /settings/VideoPlugin9 26/08/2005 16:31:43.375 VERBOSE [2] getValue: /settings/VideoPlugin9 : 26/08/2005 16:31:43.437 VERBOSE [886] getValue() loading new key/value into cache: /settings/MVPTranscodePrePlayDelay 26/08/2005 16:31:43.437 VERBOSE [886] getValue: /settings/MVPTranscodePrePlayDelay : 5500 26/08/2005 16:31:48.281 VERBOSE [885] MVP data read: 1 (8) 26/08/2005 16:31:48.281 VERBOSE [885] Responding to ping 26/08/2005 16:31:48.281 VERBOSE [885] MVP request processed 26/08/2005 16:31:48.937 VERBOSE [886] bitrate: 4248 26/08/2005 16:31:48.968 VERBOSE [886] Here we go: 0 0 0 0 0 0 0 0 26/08/2005 16:31:48.968 VERBOSE [886] Received request to seek to pos:38 26/08/2005 16:31:49.000 VERBOSE [886] Request 200000 bytes (file size:2162688 file location: 38) 26/08/2005 16:31:49.000 VERBOSE [886] about to check 26/08/2005 16:31:49.078 VERBOSE [886] Request 200000 bytes (file size:2162688 file location: 200038) 26/08/2005 16:31:49.078 VERBOSE [886] about to check 26/08/2005 16:31:49.140 VERBOSE [885] MVP data read: 1 (7) 26/08/2005 16:31:49.140 VERBOSE [885] MVP request processed 26/08/2005 16:31:49.375 VERBOSE [886] Request 200000 bytes (file size:2359296 file location: 400038) 26/08/2005 16:31:49.375 VERBOSE [886] about to check 26/08/2005 16:31:49.687 VERBOSE [886] Request 200000 bytes (file size:2490368 file location: 600038) 26/08/2005 16:31:49.687 VERBOSE [886] about to check 26/08/2005 16:31:49.750 VERBOSE [886] Request 200000 bytes (file size:2555904 file location: 800038) 26/08/2005 16:31:49.750 VERBOSE [886] about to check 26/08/2005 16:31:49.828 VERBOSE [886] Request 200000 bytes (file size:2555904 file location: 1000038) 26/08/2005 16:31:49.828 VERBOSE [886] about to check 26/08/2005 16:31:49.890 VERBOSE [886] Request 200000 bytes (file size:2621440 file location: 1200038) 26/08/2005 16:31:49.890 VERBOSE [886] about to check 26/08/2005 16:31:50.078 VERBOSE [886] Request 200000 bytes (file size:2686976 file location: 1400038) 26/08/2005 16:31:50.078 VERBOSE [886] about to check 26/08/2005 16:31:50.140 VERBOSE [886] Request 200000 bytes (file size:2686976 file location: 1600038) 26/08/2005 16:31:50.140 VERBOSE [886] about to check 26/08/2005 16:31:50.484 VERBOSE [886] Request 200000 bytes (file size:2883584 file location: 1800038) 26/08/2005 16:31:50.484 VERBOSE [886] about to check 26/08/2005 16:31:50.562 VERBOSE [886] Request 200000 bytes (file size:2883584 file location: 2000038) 26/08/2005 16:31:50.562 VERBOSE [886] about to check 26/08/2005 16:31:50.921 VERBOSE [886] Request 200000 bytes (file size:3080192 file location: 2200038) 26/08/2005 16:31:50.921 VERBOSE [886] about to check 26/08/2005 16:31:50.968 VERBOSE [886] Request 200000 bytes (file size:3080192 file location: 2400038) 26/08/2005 16:31:50.968 VERBOSE [886] about to check 26/08/2005 16:31:51.093 VERBOSE [886] Request 200000 bytes (file size:3080192 file location: 2600038) 26/08/2005 16:31:51.093 VERBOSE [886] about to check 26/08/2005 16:31:51.406 VERBOSE [886] Request 200000 bytes (file size:3211264 file location: 2800038) 26/08/2005 16:31:51.406 VERBOSE [886] about to check 26/08/2005 16:31:51.500 VERBOSE [886] Request 200000 bytes (file size:3211264 file location: 3000038) 26/08/2005 16:31:51.500 VERBOSE [886] about to check 26/08/2005 16:31:51.750 VERBOSE [886] Request 200000 bytes (file size:3342336 file location: 3200038) 26/08/2005 16:31:51.750 VERBOSE [886] about to check 26/08/2005 16:31:51.750 VERBOSE [886] Not all bytes read. Got:142298 Filesize now:3342336 26/08/2005 16:31:53.296 VERBOSE [885] MVP data read: 1 (8) 26/08/2005 16:31:53.296 VERBOSE [885] Responding to ping 26/08/2005 16:31:53.296 VERBOSE [885] MVP request processed 26/08/2005 16:31:58.343 VERBOSE [885] MVP data read: 1 (8) 26/08/2005 16:31:58.343 VERBOSE [885] Responding to ping 26/08/2005 16:31:58.343 VERBOSE [885] MVP request processed 26/08/2005 16:32:02.796 VERBOSE [886] MVP Streaming Server received STOP message 26/08/2005 16:32:02.796 VERBOSE [885] MVP data read: 1 (7) 26/08/2005 16:32:02.796 VERBOSE [885] MVP request processed 26/08/2005 16:32:02.937 VERBOSE [886] frame sent

If anyone had any ideas why this suddenly seems to stop, I'd be very greatful.

Thanks in advance

[UKGuest44]

Hmm, after a little more investigation, I have to conclude that GBPVR itself is doing something weird.

I tried to do the process manually, I ran trans2mvp from the commandline with the same command, then navigated to the file and played it manually through the MVP, with trans2mvp still transcoding.

The file played no problems and seemed fine - isn't this virtually what GBPVR itself does anyway?

Still not sure why GBPVR cant do it normally when I just try to play the file directly.

[sub]

Both your description, and you logs, are telling me your machine is not managing to transcode faster than real time. The transcode is progressing fine, but the playback reaches the end of the file and returns to the menu.

Maybe these recordings have a higher bitrate, or lots of action, which is causing the transcoding to take longer than other files.

[UKGuest44]

Thanks for the suggestion, at least that gives another idea to juggle with.

Is there any way to rule it out or confirm it definitely?

I wouldnt have thought it was that, mainly because of the reason that when I go to watch the video, and the transcoding starts, then the MVP returns to the menu, the transcoded file goes quite a bit beyond where the MVP got to.

If I pause the file right at the start, I can watch the length bar get further and further, say up to a good amount, perhaps 4 minutes. But I if I press play, it continues on for a few seconds and then returns to the main menu - even though the transcoded file went on much after that.

As for the recorindgs themselves, they shouldnt be any different to any of the other ones.

Thanks a lot for your time

[A_Brass]

Is your "H:" drive networked or local? USB, IDE, or SCSI?

[UKGuest44]

Thanks for the reply,

The H: drive is local IDE drive, and I dont think the drive is the problem, as that is where all my media content lives, of which I have no problems with.

Thanks

[sub]

Is there any way to rule it out or confirm it definitely?

I'm sure thats what happening.

...
16:31:43.890 INFO - AVI Splitter
16:31:43.890 INFO - H:\MYVIDE~1\VICARO~1\THEVIC~1.AVI
16:31:43.984 VERBOSE About to start graph
16:31:44.015 VERBOSE transcode processing started

Transcoding has started, and still in progress. All is working fine.

26/08/2005 16:31:50.921 VERBOSE [886] Request 200000 bytes (file size:3080192 file location: 2200038)
26/08/2005 16:31:50.921 VERBOSE [886] about to check
26/08/2005 16:31:50.968 VERBOSE [886] Request 200000 bytes (file size:3080192 file location: 2400038)
26/08/2005 16:31:50.968 VERBOSE [886] about to check
26/08/2005 16:31:51.093 VERBOSE [886] Request 200000 bytes (file size:3080192 file location: 2600038)
26/08/2005 16:31:51.093 VERBOSE [886] about to check
26/08/2005 16:31:51.406 VERBOSE [886] Request 200000 bytes (file size:3211264 file location: 2800038)
26/08/2005 16:31:51.406 VERBOSE [886] about to check
26/08/2005 16:31:51.500 VERBOSE [886] Request 200000 bytes (file size:3211264 file location: 3000038)
26/08/2005 16:31:51.500 VERBOSE [886] about to check
26/08/2005 16:31:51.750 VERBOSE [886] Request 200000 bytes (file size:3342336 file location: 3200038)
26/08/2005 16:31:51.750 VERBOSE [886] about to check
26/08/2005 16:31:51.750 VERBOSE [886] Not all bytes read. Got:142298 Filesize now:3342336

File is growing well, but playback catches up, and the last packet is not the full size, which tells the MVP we have reached the end of the file.

[UKGuest44]

Thanks,

Do you believe that increasing the MVP Transcode pre-play delay could help?

[sub]

Do you believe that increasing the MVP Transcode pre-play delay could help?

Yes, but it'll most likely only let you play it for a little bit longer. Give it a go though.

[UKGuest44]

Thanks! That's solved it!

Seems it just needed that little jog at the start. now I'm getting through it, the file length keeps getting further from the current position and the gap growing so it shouldn't catch up and it's playing fine

Thanks again