Bug #1850

ST ends playback before the end of the actual movie length with log message "Playback reached EOF: Not enough space (-12)"

Added by Rural Hunter almost 7 years ago. Updated almost 7 years ago.

Status:FixedStart date:01/11/2014
Priority:NormalDue date:
Assignee:Andreas Smas% Done:

100%

Category:Video playback
Target version:4.4
Found in version:latest Platform:PS3

Description

It's hard to reproduce. Sometime the playback just ends and return back to list view and marked the video as played. Fast forward to the abort point and the resume playing is fine. The video is more than 2 hours and during the playback it happened two times. Here is the log from one of them:
00:00:55.934: VDEC [DEBUG]:Waiting for end sequence
00:00:55.937: VDEC [DEBUG]:Waiting for end sequence -> done
00:26:43.759: Freetype [DEBUG]:Unloading 'Ubuntu Mono' [Regular] originally from dataroot://resources/fonts/UbuntuMono-Regular.ttf
00:26:43.812: Freetype [DEBUG]:Loaded 'Ubuntu Mono' [Regular] domain:11
00:45:56.257: Freetype [DEBUG]:Unloading 'Ubuntu Mono' [Regular] originally from dataroot://resources/fonts/UbuntuMono-Regular.ttf
00:45:56.318: Freetype [DEBUG]:Loaded 'Ubuntu Mono' [Regular] domain:11
00:57:58.025: Video [DEBUG]:Playback reached EOF: Not enough space
00:58:16.332: Video [DEBUG]:Playback reached 72%, counting as played (ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv)
00:58:16.332: Video [DEBUG]:Stopped playback of ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv
00:58:16.333: THREADS [DEBUG]:Waiting for thread 0x1070088
00:58:16.333: VDEC [DEBUG]:Waiting for end sequence
00:58:16.335: VDEC [DEBUG]:Waiting for end sequence -> done
00:58:16.344: THREADS [DEBUG]:Thread 0x1070088 (audio decoder) exiting
00:58:16.345: THREADS [DEBUG]:Thread 0x1070088 joined
00:58:16.346: VDEC [DEBUG]:Freeing picture list
00:58:16.346: VDEC [DEBUG]:Free picture 0x40503bf8
00:58:16.346: VDEC [DEBUG]:Free RSX mem 4a20950 +1025280
00:58:16.347: VDEC [DEBUG]:Free picture 0x40887060
00:58:16.347: VDEC [DEBUG]:Free RSX mem 4b1ae50 +1025280
00:58:16.348: VDEC [DEBUG]:Free picture 0x4072ae80
00:58:16.348: VDEC [DEBUG]:Free RSX mem 4e09d50 +1025280
00:58:16.349: VDEC [DEBUG]:Free picture 0x401f1d00
00:58:16.350: VDEC [DEBUG]:Free RSX mem 468af70 +1025280
00:58:16.350: VDEC [DEBUG]:Free picture 0x40f07a78
00:58:16.351: VDEC [DEBUG]:Free RSX mem 4ffe750 +1025280
00:58:16.351: VDEC [DEBUG]:Free picture 0x401bfb90
00:58:16.352: VDEC [DEBUG]:Free RSX mem 439c070 +1025280
00:58:16.354: VDEC [DEBUG]:Cell decoder closed
00:58:16.354: Freetype [DEBUG]:Unloading 'Arial' [Regular] originally from memory
00:58:16.364: vp [DEBUG]:Waiting for event
00:58:16.410: THREADS [DEBUG]:Waiting for thread 0x107006d
00:58:16.432: THREADS [DEBUG]:Thread 0x107006d (video decoder) exiting
00:58:16.447: THREADS [DEBUG]:Thread 0x107006e (video player) exiting
00:58:16.447: THREADS [DEBUG]:Thread 0x107006d joined
00:58:16.493: THREADS [DEBUG]:Thread 0x107006c (PC:mp) exiting
00:58:16.493: THREADS [DEBUG]:Waiting for thread 0x107006c
00:58:16.494: THREADS [DEBUG]:Thread 0x107006c joined

showtime.log.0 (49.1 KB) Leonid Protasov, 01/21/2014 06:20 AM

showtime.log.0 (135 KB) Leonid Protasov, 01/21/2014 07:27 AM

Associated revisions

Revision cf9937fc
Added by Andreas Smas almost 7 years ago

Try to add some debug to check why we suddenly stop to play video files in the middle

refs #1852
refs #1850

Change included in version 4.3.707

Revision 8e4994da
Added by Andreas Smas almost 7 years ago

ps3: Log when we fail to alloc memory

refs #1850
refs #1847

Change included in version 4.3.721

Revision 5addbaf2
Added by Andreas Smas almost 7 years ago

Get rid of the "short read" debug

refs #1852
refs #1850

Change included in version 4.3.727

Revision f3c8995b
Added by Andreas Smas almost 7 years ago

ps3: Increate TLSF pool size

refs #1852
refs #1850

Change included in version 4.3.728

History

#1 Updated by Leonid Protasov almost 7 years ago

  • Subject changed from Playback aborts half way to Sometimes playback from NTFS drive reaches EOF before the end of the actual movie length

#2 Updated by Leonid Protasov almost 7 years ago

Platform is PS3?

#3 Updated by Rural Hunter almost 7 years ago

ah yes it's ps3. Sorry forgot to change the platform

#4 Updated by Leonid Protasov almost 7 years ago

  • Platform changed from Linux to PS3

#5 Updated by Andreas Smas almost 7 years ago

  • Target version set to 4.4

#6 Updated by Andreas Smas almost 7 years ago

I've added some more logging trying to figure out why this happens. Please keep an eye open.

#7 Updated by Andreas Smas almost 7 years ago

  • Status changed from New to Need feedback

#8 Updated by Rural Hunter almost 7 years ago

I replayed the video again and reproduced the problem. Here is the log:

00:00:20.502: navigator [INFO]:Opening ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv
00:00:20.504: THREADS [DEBUG]:Created thread fa_open (0x104008d)
00:00:20.506: THREADS [DEBUG]:Thread 0x104008d (fa_open) exiting
00:00:20.575: THREADS [DEBUG]:Created thread PC:mp (0x104008e)
00:00:20.577: THREADS [DEBUG]:Created thread video decoder (0x104008f)
00:00:20.578: THREADS [DEBUG]:Created thread video player (0x1040090)
00:00:20.578: vp [DEBUG]:Waiting for event
00:00:20.578: vp [DEBUG]:Playing ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv flags:0x1
00:00:20.580: media [DEBUG]:Settings initialized for URL ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv
00:00:20.583: AVSYNC [DEBUG]:Set to 0 ms
00:00:20.587: SVSYNC [DEBUG]:Set to 0s
00:00:20.713: Video [DEBUG]:Starting playback of ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv (matroska,webm)
00:00:20.730: Probe [DEBUG]: Stream #0: Video: h264 (High), yuv420p, 1280x534
00:00:20.730: Probe [DEBUG]: Stream #1: Audio: ac3, 48000 Hz, 5.1, fltp, 640 kb/s
00:00:20.731: Probe [DEBUG]: Stream #2: Attachment: [0][0][0][0] / 0x0000
00:00:20.737: Subscanner [DEBUG]:Starting subtitle scan for Captain Phillips (imdbid:tt1535109) year:0 season:-1 episode:-1 duration:8044 opensubhash:02ec2a664b792a01
00:00:20.739: THREADS [DEBUG]:Created thread subscanner (0x1040091)
00:00:20.741: Video [DEBUG]:Scanning for subs in ntfs0://娆х編/ for Captain.Phillips.2013.720p.BluRay.x264-WiKi
00:00:20.742: Video [DEBUG]: Stream #0: Video: h264 (High), yuv420p, 1280x534
00:00:20.748: THREADS [DEBUG]:Thread 0x1040091 (subscanner) exiting
00:00:20.773: VDEC [DEBUG]:Opening codec h264 level 42 using 54157309 bytes of RAM
00:00:20.777: VDEC [DEBUG]:Cell accelerated codec created using 54157309 bytes of RAM
00:00:20.790: Video [DEBUG]: Stream #0: Codec created
00:00:20.792: Video [DEBUG]: Stream #1: Audio: ac3, 48000 Hz, 5.1, fltp, 640 kb/s
00:00:20.792: Video [DEBUG]: Stream #1: Codec created
00:00:20.793: Video [DEBUG]: Stream #2: Attachment: [0][0][0][0] / 0x0000
00:00:20.793: Video [DEBUG]: filename: arial.ttf mimetype: application/x-truetype-font size: 772192
00:00:20.872: Freetype [DEBUG]:Loaded 'Arial' [Regular] domain:12
00:00:20.873: THREADS [DEBUG]:Created thread audio decoder (0x1040095)
00:00:20.958: Video [DEBUG]:Selecting audio track libav:1
00:00:20.959: Video [DEBUG]:Selecting subtitle track ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.chs.srt
00:00:20.959: Subtitles [DEBUG]:Trying to load ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.chs.srt
00:00:21.032: Subtitles [DEBUG]:Loaded ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.chs.srt OK
00:00:21.053: audio [DEBUG]:Codec changed to ac3
00:00:21.115: AUDIO [DEBUG]:The state is 1
00:00:21.117: AUDIO [DEBUG]:PS3 audio port 0 opened (8 channels)
00:00:21.122: Audio [DEBUG]:Converting from [5.1 48000Hz fltp] to [7.1 48000Hz flt]
00:03:12.591: THREADS [DEBUG]:Created thread FTP-session (0x1040097)
00:03:12.613: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:03:12.618: THREADS [DEBUG]:Thread 0x1040097 (FTP-session) exiting
00:03:16.797: THREADS [DEBUG]:Created thread FTP-session (0x1040098)
00:03:16.798: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:03:16.798: THREADS [DEBUG]:Thread 0x1040098 (FTP-session) exiting
00:04:20.004: THREADS [DEBUG]:Created thread FTP-session (0x1040099)
00:04:20.025: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:04:20.050: THREADS [DEBUG]:Thread 0x1040099 (FTP-session) exiting
00:05:38.416: THREADS [DEBUG]:Created thread FTP-session (0x104009a)
00:05:38.417: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:05:38.418: THREADS [DEBUG]:Thread 0x104009a (FTP-session) exiting
00:07:13.705: THREADS [DEBUG]:Created thread FTP-session (0x104009b)
00:07:13.706: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:07:13.707: THREADS [DEBUG]:Thread 0x104009b (FTP-session) exiting
00:30:22.747: Freetype [DEBUG]:Unloading 'Ubuntu Mono' [Regular] originally from dataroot://resources/fonts/UbuntuMono-Regular.ttf
00:30:22.811: Freetype [DEBUG]:Loaded 'Ubuntu Mono' [Regular] domain:11
00:40:24.996: Video [DEBUG]:Playback reached EOF: Not enough space (-12)
00:40:43.214: Video [DEBUG]:Playback reached 29%, counting as played (ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv)
00:40:43.214: Video [DEBUG]:Stopped playback of ntfs0://娆х編/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv
00:40:43.214: VDEC [DEBUG]:Waiting for end sequence
00:40:43.215: THREADS [DEBUG]:Waiting for thread 0x1040095
00:40:43.217: VDEC [DEBUG]:Waiting for end sequence -> done
00:40:43.225: THREADS [DEBUG]:Thread 0x1040095 (audio decoder) exiting
00:40:43.240: THREADS [DEBUG]:Thread 0x1040095 joined
00:40:43.240: VDEC [DEBUG]:Freeing picture list
00:40:43.241: VDEC [DEBUG]:Free picture 0x4074f418
00:40:43.241: VDEC [DEBUG]:Free RSX mem 43ead70 +1025280
00:40:43.242: VDEC [DEBUG]:Free picture 0x40524a70
00:40:43.242: VDEC [DEBUG]:Free RSX mem 4ac58f0 +1025280
00:40:43.243: VDEC [DEBUG]:Free picture 0x408024a8
00:40:43.243: VDEC [DEBUG]:Free RSX mem 4cba2f0 +1025280
00:40:43.245: VDEC [DEBUG]:Cell decoder closed
00:40:43.246: Freetype [DEBUG]:Unloading 'Arial' [Regular] originally from memory
00:40:43.248: vp [DEBUG]:Waiting for event
00:40:43.287: THREADS [DEBUG]:Waiting for thread 0x104008f
00:40:43.295: THREADS [DEBUG]:Thread 0x1040090 (video player) exiting
00:40:43.299: THREADS [DEBUG]:Thread 0x104008f (video decoder) exiting
00:40:43.299: THREADS [DEBUG]:Thread 0x104008f joined
00:40:43.303: THREADS [DEBUG]:Thread 0x104008e (PC:mp) exiting
00:40:43.303: THREADS [DEBUG]:Waiting for thread 0x104008e
00:40:43.304: THREADS [DEBUG]:Thread 0x104008e joined

#9 Updated by Andreas Smas almost 7 years ago

  • Status changed from Need feedback to Accepted

Could it be some kind of memory leak perhaps?

Arghh. This is very annoying :-(

#10 Updated by Leonid Protasov almost 7 years ago

FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
4.3.970? 4.3.719 is just out only... And maybe that leak comes from ftp server firing up? As the error appears after that...

#11 Updated by Rural Hunter almost 7 years ago

There are some additional changes on my build(to load a customized font etc but nothing related to video playback) so the build number is larger than the official version number. The error occurred after more than 30 mins after the ftp session log. So I guess it's not related to the problem.

#12 Updated by Leonid Protasov almost 7 years ago

Is the bug reproducible only from NTFS drive? Can you test the same from USB/SMB etc?

#13 Updated by Rural Hunter almost 7 years ago

I will try to get time to split it to FAT32 driver and test it. From what I've discovered so far, this problem seems is related to specific video file only. I didn't get problem with other files on NTFS.

#14 Updated by Rural Hunter almost 7 years ago

it could reproduce on FAT32 too:
00:00:23.012: navigator [INFO]:Opening file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv
00:00:23.041: THREADS [DEBUG]:Created thread fa_open (0x10400ce)
00:00:23.178: THREADS [DEBUG]:Thread 0x10400ce (fa_open) exiting
00:00:23.209: THREADS [DEBUG]:Created thread PC:mp (0x10400cf)
00:00:23.211: THREADS [DEBUG]:Created thread video decoder (0x10400d0)
00:00:23.212: THREADS [DEBUG]:Created thread video player (0x10400d1)
00:00:23.212: vp [DEBUG]:Waiting for event
00:00:23.212: vp [DEBUG]:Playing file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv flags:0x1
00:00:23.213: media [DEBUG]:Settings initialized for URL file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv
00:00:23.217: AVSYNC [DEBUG]:Set to 0 ms
00:00:23.218: SVSYNC [DEBUG]:Set to 0s
00:00:23.623: Video [DEBUG]:Starting playback of file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv (matroska,webm)
00:00:23.623: Probe [DEBUG]: Stream #0: Video: h264 (High), yuv420p, 1280x534
00:00:23.623: Probe [DEBUG]: Stream #1: Audio: ac3, 48000 Hz, 5.1, fltp, 640 kb/s
00:00:23.624: Probe [DEBUG]: Stream #2: Attachment: [0][0][0][0] / 0x0000
00:00:23.628: Subscanner [DEBUG]:Starting subtitle scan for 鑿插埄鏅柉鑸归暱 (imdbid:tt1535109) year:0 season:-1 episode:-1 duration:8044 opensubhash:02ec2a664b792a01
00:00:23.640: THREADS [DEBUG]:Created thread subscanner (0x10400d2)
00:00:23.641: Video [DEBUG]:Scanning for subs in file:///dev_usb000/Video/ for Captain.Phillips.2013.720p.BluRay.x264-WiKi
00:00:23.641: Video [DEBUG]: Stream #0: Video: h264 (High), yuv420p, 1280x534
00:00:23.666: VDEC [DEBUG]:Opening codec h264 level 42 using 54157309 bytes of RAM
00:00:23.670: VDEC [DEBUG]:Cell accelerated codec created using 54157309 bytes of RAM
00:00:23.671: Video [DEBUG]: Stream #0: Codec created
00:00:23.672: Video [DEBUG]: Stream #1: Audio: ac3, 48000 Hz, 5.1, fltp, 640 kb/s
00:00:23.672: Video [DEBUG]: Stream #1: Codec created
00:00:23.673: Video [DEBUG]: Stream #2: Attachment: [0][0][0][0] / 0x0000
00:00:23.683: Video [DEBUG]: filename: arial.ttf mimetype: application/x-truetype-font size: 772192
00:00:24.046: GLW [DEBUG]:Load of tmdb:image:poster:/mO5UuERHkeqNOdd84SOsyOQ3B9O.jpg was aborted
00:00:24.046: GLW [DEBUG]:Load of tmdb:image:poster:/t0mFjbffLsPr1DpxV2QmjdZnDnA.jpg was aborted
00:00:24.047: GLW [DEBUG]:Load of tmdb:image:poster:/cjNvhte8I318miZucl9MIFFyWQJ.jpg was aborted
00:00:24.256: Freetype [DEBUG]:Loaded 'Arial' [Regular] domain:12
00:00:24.257: THREADS [DEBUG]:Created thread audio decoder (0x10400d6)
00:00:24.315: Video [DEBUG]:Selecting audio track libav:1
00:00:24.325: audio [DEBUG]:Codec changed to ac3
00:00:24.750: AUDIO [DEBUG]:The state is 1
00:00:24.762: AUDIO [DEBUG]:PS3 audio port 0 opened (8 channels)
00:00:24.763: Audio [DEBUG]:Converting from [5.1 48000Hz fltp] to [7.1 48000Hz flt]
00:00:25.166: Video [DEBUG]:Selecting subtitle track file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.chs.srt
00:00:25.167: Subtitles [DEBUG]:Trying to load file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.chs.srt
00:00:25.167: THREADS [DEBUG]:Thread 0x10400d2 (subscanner) exiting
00:00:25.240: Subtitles [DEBUG]:Loaded file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.chs.srt OK
00:00:35.547: UPNP [DEBUG]:Created subscription for ConnectionManager:2 callback: http://192.168.11.2:2869/upnp/eventing/uknsftktsg SID: uuid:ab1e1b80-0f10-1743-f38e-7b949ede3ff9 (timeout: 1800 seconds)
00:00:35.640: UPNP [DEBUG]:Created subscription for RenderingControl:2 callback: http://192.168.11.2:2869/upnp/eventing/prmizefdpj SID: uuid:a5de9bcc-3e3f-0b2d-3e44-cd0988047d95 (timeout: 1800 seconds)
00:00:35.776: UPNP [DEBUG]:Created subscription for AVTransport:2 callback: http://192.168.11.2:2869/upnp/eventing/ppfuuxdwkm SID: uuid:7fd9ec05-bc3b-61ef-e963-308b119badeb (timeout: 1800 seconds)
00:00:36.226: UPNP [DEBUG]:Deleted subscription for ConnectionManager:2 callback: http://192.168.11.2:2869/upnp/eventing/uknsftktsg SID: uuid:ab1e1b80-0f10-1743-f38e-7b949ede3ff9 -- Requested by subscriber
00:00:36.319: UPNP [DEBUG]:Deleted subscription for RenderingControl:2 callback: http://192.168.11.2:2869/upnp/eventing/prmizefdpj SID: uuid:a5de9bcc-3e3f-0b2d-3e44-cd0988047d95 -- Requested by subscriber
00:00:36.450: UPNP [DEBUG]:Deleted subscription for AVTransport:2 callback: http://192.168.11.2:2869/upnp/eventing/ppfuuxdwkm SID: uuid:7fd9ec05-bc3b-61ef-e963-308b119badeb -- Requested by subscriber
00:00:48.607: GLW [DEBUG]:Load of tmdb:image:poster:/83eJJlHscLsi9DHsqsyk1hIXL83.jpg was aborted
00:02:38.430: THREADS [DEBUG]:Created thread FTP-session (0x10400d8)
00:02:38.450: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:02:38.450: THREADS [DEBUG]:Thread 0x10400d8 (FTP-session) exiting
00:02:49.873: THREADS [DEBUG]:Created thread FTP-session (0x10400d9)
00:02:49.873: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:02:49.874: THREADS [DEBUG]:Thread 0x10400d9 (FTP-session) exiting
00:03:12.288: THREADS [DEBUG]:Created thread FTP-session (0x10400da)
00:03:12.289: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:03:12.317: THREADS [DEBUG]:Thread 0x10400da (FTP-session) exiting
00:04:43.848: THREADS [DEBUG]:Created thread FTP-session (0x10400db)
00:04:43.849: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:04:43.850: THREADS [DEBUG]:Thread 0x10400db (FTP-session) exiting
00:06:34.289: THREADS [DEBUG]:Created thread FTP-session (0x10400dc)
00:06:34.290: FTP-SERVER [DEBUG]:SEND: 220 192.168.11.6 FTP server (Showtime on PS3 Version 4.3.970.g3af1d) ready.
00:06:34.290: THREADS [DEBUG]:Thread 0x10400dc (FTP-session) exiting
00:29:32.513: Freetype [DEBUG]:Unloading 'Ubuntu Mono' [Regular] originally from dataroot://resources/fonts/UbuntuMono-Regular.ttf
00:29:32.567: Freetype [DEBUG]:Loaded 'Ubuntu Mono' [Regular] domain:11
00:34:39.947: UPNP [DEBUG]:Created subscription for ConnectionManager:2 callback: http://192.168.11.8:2869/upnp/eventing/xqgqynqssh SID: uuid:87d42c89-658a-2530-c78a-5855fb3511d9 (timeout: 1800 seconds)
00:34:40.071: UPNP [DEBUG]:Created subscription for RenderingControl:2 callback: http://192.168.11.8:2869/upnp/eventing/aipsymjdqr SID: uuid:32579011-e615-cf13-5880-5a913cd8d814 (timeout: 1800 seconds)
00:34:40.149: UPNP [DEBUG]:Created subscription for AVTransport:2 callback: http://192.168.11.8:2869/upnp/eventing/hpguhvtqvs SID: uuid:fac7ac10-6154-ce7a-c6b0-b9214c07dac8 (timeout: 1800 seconds)
00:34:40.660: UPNP [DEBUG]:Deleted subscription for ConnectionManager:2 callback: http://192.168.11.8:2869/upnp/eventing/xqgqynqssh SID: uuid:87d42c89-658a-2530-c78a-5855fb3511d9 -- Requested by subscriber
00:34:40.820: UPNP [DEBUG]:Deleted subscription for AVTransport:2 callback: http://192.168.11.8:2869/upnp/eventing/hpguhvtqvs SID: uuid:fac7ac10-6154-ce7a-c6b0-b9214c07dac8 -- Requested by subscriber
00:34:43.780: UPNP [DEBUG]:Deleted subscription for RenderingControl:2 callback: http://192.168.11.8:2869/upnp/eventing/aipsymjdqr SID: uuid:32579011-e615-cf13-5880-5a913cd8d814 -- Requested by subscriber
00:50:50.433: Video [DEBUG]:Playback reached EOF: Not enough space (-12)
00:51:10.280: Video [DEBUG]:Playback reached 37%, counting as played (file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv)
00:51:10.281: Video [DEBUG]:Stopped playback of file:///dev_usb000/Video/Captain.Phillips.2013.720p.BluRay.x264-WiKi.mkv
00:51:10.281: THREADS [DEBUG]:Waiting for thread 0x10400d6
00:51:10.281: VDEC [DEBUG]:Waiting for end sequence
00:51:10.283: VDEC [DEBUG]:Waiting for end sequence -> done
00:51:10.293: THREADS [DEBUG]:Thread 0x10400d6 (audio decoder) exiting
00:51:10.293: THREADS [DEBUG]:Thread 0x10400d6 joined
00:51:10.294: VDEC [DEBUG]:Freeing picture list
00:51:10.294: VDEC [DEBUG]:Free picture 0x401b85f8
00:51:10.295: VDEC [DEBUG]:Free RSX mem 4284fd0 +1025280
00:51:10.295: VDEC [DEBUG]:Free picture 0x40578cd0
00:51:10.296: VDEC [DEBUG]:Free RSX mem 4862dd0 +1025280
00:51:10.296: VDEC [DEBUG]:Free picture 0x41a6d020
00:51:10.296: VDEC [DEBUG]:Free RSX mem 4573ed0 +1025280
00:51:10.299: VDEC [DEBUG]:Cell decoder closed
00:51:10.299: Freetype [DEBUG]:Unloading 'Arial' [Regular] originally from memory
00:51:10.301: vp [DEBUG]:Waiting for event
00:51:10.350: THREADS [DEBUG]:Waiting for thread 0x10400d0
00:51:10.350: THREADS [DEBUG]:Thread 0x10400d1 (video player) exiting
00:51:10.354: THREADS [DEBUG]:Thread 0x10400d0 (video decoder) exiting
00:51:10.355: THREADS [DEBUG]:Thread 0x10400d0 joined
00:51:10.359: THREADS [DEBUG]:Thread 0x10400cf (PC:mp) exiting
00:51:10.359: THREADS [DEBUG]:Waiting for thread 0x10400cf
00:51:10.359: THREADS [DEBUG]:Thread 0x10400cf joined

#15 Updated by Andreas Smas almost 7 years ago

  • Status changed from Accepted to Need feedback

Hm and this last log output you pasted, does it run from a build that includes the out-of-memory log messages I added? (in my rev 4.3.721 (8e4994da))

#16 Updated by Rural Hunter almost 7 years ago

No. I will re-test with the latest source.

#17 Updated by Leonid Protasov almost 7 years ago

  • Subject changed from Sometimes playback from NTFS drive reaches EOF before the end of the actual movie length to Sometimes ST ends playback before the end of the actual movie length with debug message "Playback reached EOF: Not enough space (-12)"

#18 Updated by Rural Hunter almost 7 years ago

FYI, the same video played fine from start to end on the Linux build from the latest source.

#19 Updated by Leonid Protasov almost 7 years ago

What I see in your logs is that error is always is preceeded with FTP session. Maybe that low memory condition occures when FTP server allocates some memory at the playback time on PS3?

#20 Updated by Rural Hunter almost 7 years ago

Not sure. It's also strange where the ftp session came from as I didn't access the ftp server in showtime during the playback.

#21 Updated by Leonid Protasov almost 7 years ago

That can be some virus sitting on the net where is your PS3 connected.
To check this bug you can do the following:
1. Update to 4.3.724
2. Go to settings:dev and enable logging file list
3. Switch off FTP server and play that movie - I bet it will play fine

After that:
1. Enable FTP server
2. Start playing movie
3. Connect from PC by FTP to ST and try to transfer files from PS3 or to PS3...

Don't forget to attach logs here :)

#22 Updated by Leonid Protasov almost 7 years ago

  • Subject changed from Sometimes ST ends playback before the end of the actual movie length with debug message "Playback reached EOF: Not enough space (-12)" to ST ends playback before the end of the actual movie length with log message "Playback reached EOF: Not enough space (-12)" when some FTP sessions are created in the background

#23 Updated by Leonid Protasov almost 7 years ago

I just tested to play movie on my PS3 and connect to FTP server at the same time. All activity is logged even if FTP debug is off in settings. And your FTP record in log say that something is connecting to FTP port but doesn't try to log in. Looks like port scanner is active on the net.

I tried to transfer files to/from PS3 to reproduce low memory issue - no chance mem free is about 36MByte.

When you play movie - can you keep on meminfo that is displayed on screen if you press left stick. I wonder what is free and used mem values it shows when EOF happens or even when it is playing well...

#24 Updated by Leonid Protasov almost 7 years ago

  • Subject changed from ST ends playback before the end of the actual movie length with log message "Playback reached EOF: Not enough space (-12)" when some FTP sessions are created in the background to ST ends playback before the end of the actual movie length with log message "Playback reached EOF: Not enough space (-12)"

alid UTF-8. Decoded as windows-1250 (detected language: pl) 00:01:35.697: Subtitles [DEBUG]:Loaded http://dl.opensubtitles.org/en/download/filead/src-api/vrf-a0d1a0a157/1953907267.gz OK 00:02:05.382: Settings [DEBUG]:Wrote 12661 bytes to "/dev_hdd0/game/HTSS00003/USRDIR/settings/settings/httpcookies" 00:02:07.392: audio [DEBUG]:Master volume set to 1.000000 dB 00:02:07.414: Media [DEBUG]:Seeking by dropping 1907 audio packets and 251+102 video packets from queue 00:02:07.421: Video [DEBUG]:seek direct to 52.54 (52538000 - 0) 00:02:07.458: libav [DEBUG]:Short read wanted:32768 got:18721 00:02:07.544: VDEC [DEBUG]:Waiting for end sequence 00:02:07.568: VDEC [DEBUG]:Waiting for end sequence -> done 00:02:08.269: audio [DEBUG]:Master volume set to 0.000000 dB 00:02:08.504: audio [DEBUG]:Master volume set to -1.000000 dB 00:02:09.445: Settings [DEBUG]:Wrote 28 bytes to "/dev_hdd0/game/HTSS00003/USRDIR/settings/settings/audiomixer" 00:16:18.567: SPUMINER [DEBUG]:SPU-2 found nonce 0x6b9ba132 for work 27b6 00:17:45.878: SPUMINER [DEBUG]:SPU-5 found nonce 0xeba0c141 for work 27b8 00:22:02.781: SPUMINER [DEBUG]:SPU-5 found nonce 0xebaf3661 for work 27bc 00:35:03.891: SPUMINER [DEBUG]:SPU-5 found nonce 0xebda1cf9 for work 27cd 00:41:16.078: MEMORY [ERROR]:memalign(32,102441) failed 00:41:16.100: Video [DEBUG]:Playback reached EOF: Not enough space (-12) 00:41:35.568: Video [DEBUG]:Playback reached 29%, counting as played (file:///dev_hdd0/Captain.Phillips.2013.BluRay.720p.x264.DTS.mkv) 00:41:35.569: Video [DEBUG]:Stopped playback of file:///dev_hdd0/Captain.Phillips.2013.BluRay.720p.x264.DTS.mkv

#25 Updated by Rural Hunter almost 7 years ago

Haven't got time to test it on PS3 yet. But I doubt the conclusion that ftp is the cause of this problem. I did ftped several files to showtime(but not during playing this video) and there was not any problem. When the problem happened on that specific video, there was actually no ftp task running.

#26 Updated by Andreas Smas almost 7 years ago

  • Status changed from Need feedback to Accepted

Leonid Protasov wrote:

00:41:16.078: MEMORY [ERROR]:memalign(32,102441) failed
00:41:16.100: Video [DEBUG]:Playback reached EOF: Not enough space (-12)

So it's an out-of-memory issue after all. Will look into this later.

#27 Updated by Leonid Protasov almost 7 years ago

Oops. That log is wrong. Don't look at it :)

#28 Updated by Leonid Protasov almost 7 years ago

Take a look at this log. This time it is correct.
Looks like I found much easier way to reproduce:
1. Start playing big MKV movie (I used 8.3Gbyte 720p).
2. Goto page settings and select "Chapters"
3. Wait some time and return
Go again and eventually you will get that memalign...

#29 Updated by Leonid Protasov almost 7 years ago

After increasing TLSF pool size - file played well with ST 4.3.732.
Take a look at the log (I turned mem debug on) maybe you will notice something interesting.
http://sprunge.us/QRDf

Starting playing file from item list:
00:01:28.888: MEM [DEBUG]:SysTotal: 218112 kB, SysFree: 80472 kB, Memory Used: 6516 kB, Fragments: 0 kB, Inactive: 91546 kB

Playing starting:
00:01:29.940: MEM [DEBUG]:SysTotal: 218112 kB, SysFree: 79512 kB, Memory Used: 9970 kB, Fragments: 0 kB, Inactive: 88080 kB

Subscanner kicks in and play buffer is growing:
00:01:30.948: MEM [DEBUG]:SysTotal: 218112 kB, SysFree: 23832 kB, Memory Used: 23044 kB, Fragments: 4 kB, Inactive: 74906 kB

Subscanner exits:
00:01:36.118: MEM [DEBUG]:SysTotal: 218112 kB, SysFree: 20376 kB, Memory Used: 44306 kB, Fragments: 7 kB, Inactive: 53414 kB

Movie ends playing:
02:16:55.289: MEM [DEBUG]:SysTotal: 218112 kB, SysFree: 19480 kB, Memory Used: 18303 kB, Fragments: 4 kB, Inactive: 79503 kB

UI returns to the item list:
02:16:56.291: MEM [DEBUG]:SysTotal: 218112 kB, SysFree: 76376 kB, Memory Used: 10447 kB, Fragments: 3 kB, Inactive: 87587 kB

We got some leaks?

#30 Updated by Leonid Protasov almost 7 years ago

Today I tried 1080p 17gbyte movie from internal hdd. Played well no eof lowmem issue. But I still able to make eof with lowmem if use time seek ribbon. I beleive that ribbon has some kind of memleak.

#31 Updated by Leonid Protasov almost 7 years ago

  • Status changed from Accepted to Fixed
  • % Done changed from 0 to 100

Issue should be fixed in 4.3.738

Also available in: Atom PDF