Strange problem.
I've got some mkv's that don't want to stream under 1.03. In fact, the problem started with 1.02, I was just too lazy to report it. The same mkv works fine in 0.99. All testing using mencode with default settings.
PMS starts up fine. I see the mkv thumbnail in the ps3. I select it to play with mencode. The screen goes black, and stays black. The on screen display show dts and mpeg2 (with no bitrate), the total length of the film, but the timer just sits at 00:00:00.
I look at the pms gui and I see that it's transcoding away, filling up the buffer, but it's not streaming.
If I select avisynth/mencode, it works (but I get 2 ch sound). See debug log snippet below.
Oh well, back to 0.99.
[Thread-45] DEBUG 16:07:13.785 Opened handler on socket Socket[addr=/192.168.0.98,port=65247,localport=5001]
[Thread-45] DEBUG 16:07:13.785 Received on socket: POST /upnp/control/content_directory HTTP/1.1
[Thread-45] DEBUG 16:07:13.785 Received on socket: X-AV-Client-Info: av=5.0; cn="Sony Computer Entertainment Inc."; mn="PLAYSTATION 3"; mv="1.0";
[Thread-45] DEBUG 16:07:13.785 Received on socket: Host: 192.168.0.7:5001
[Thread-45] DEBUG 16:07:13.785 Received on socket: User-Agent: UPnP/1.0 DLNADOC/1.00
[Thread-45] DEBUG 16:07:13.785 Received on socket: Content-Length: 903
[Thread-45] DEBUG 16:07:13.785 Received on socket: Content-Type: text/xml; charset="utf-8"
[Thread-45] DEBUG 16:07:13.785 Received on socket: SOAPACTION: "urn:schemas-upnp-org:service:ContentDirectory:1#Browse"
[Thread-45] INFO 16:07:13.987 HTTP: upnp/control/content_directory / 0-0
[Thread-45] DEBUG 16:07:13.987 Wrote on socket: HTTP/1.1 200 OK
[Thread-45] DEBUG 16:07:13.987 Wrote on socket: CONTENT-TYPE: text/xml; charset="utf-8"
[Thread-45] DEBUG 16:07:13.987 Searching for objectId: 0$0 with children option: false
[Thread-45] DEBUG 16:07:13.987 Search extension for list1.txt
[Thread-45] DEBUG 16:07:13.987 Wrote on socket: Server: Windows Vista-x86-6.0 UPnP/1.0, PMS
[Thread-45] DEBUG 16:07:13.987 Wrote on socket: Content-Length: 1022
[Thread-45] DEBUG 16:07:13.987 Wrote on socket:
[Thread-45] DEBUG 16:07:13.987 Close Connection
[Thread-46] DEBUG 16:07:19.697 Opened handler on socket Socket[addr=/192.168.0.98,port=65246,localport=5001]
[Thread-46] DEBUG 16:07:19.697 Received on socket: GET /get/0$0$5/Test1.mkv HTTP/1.1
[Thread-46] DEBUG 16:07:19.697 Received on socket: Host: 192.168.0.7:5001
[Thread-46] DEBUG 16:07:19.697 Received on socket: User-Agent: PLAYSTATION 3
[Thread-46] DEBUG 16:07:19.713 Received on socket: Connection: Keep-Alive
[Thread-46] DEBUG 16:07:19.713 Received on socket: Accept-Encoding: identity
[Thread-46] INFO 16:07:19.713 HTTP: get/0$0$5/Test1.mkv / 0-0
[Thread-46] DEBUG 16:07:19.713 Wrote on socket: HTTP/1.1 200 OK
[Thread-46] DEBUG 16:07:19.713 Searching for objectId: 0$0$5 with children option: false
[Thread-46] DEBUG 16:07:19.713 Asked stream chunk [0-0] timeseek: 0.0 of Test1.mkv and player MEncoder
[Thread-46] TRACE 16:07:19.713 Starting transcode of Test1.mkv
[Thread-46] INFO 16:07:19.713 Creating pipe \\.\pipe\mencoder1232399239713
[Thread-47] INFO 16:07:19.853 Waiting for pipe connection \\.\pipe\mencoder1232399239713
[Timer-1] DEBUG 16:07:19.853 Buffered Space: 0 bytes
[win32/mencoder.exe] INFO 16:07:19.947 Starting C:\Program Files\PS3 Media Server\win32\mencoder.exe -ss 0 -quiet E:\TVersity-E\Test1.mkv -quiet -quiet -oac lavc -of mpeg -mpegopts format=mpeg2:muxrate=500000:vbuf_size=1194:abuf_size=64 -ovc lavc -channels 6 -lavdopts debug=0:threads=2 -lavcopts autoaspect=1:vcodec=mpeg2video:acodec=ac3:abitrate=384:threads=2:keyint=1:vqscale=1:vqmin=2 -ass -nofontconfig -subcp cp1252 -alang eng,fre,jpn,ger -ass-color ffffff00 -ass-border-color 00000000 -ass-font-scale 1.0 -ass-force-style FontName=Arial,Outline=1,Shadow=1,MarginV=10 -slang eng,fre,jpn,ger -quiet -quiet -quiet -quiet -ofps 24000/1001 -quiet -quiet -af lavcresample=48000 -srate 48000 -o \\.\pipe\mencoder1232399239713
[win32/mencoder.exe] INFO 16:07:19.978 Reading pipe: \\.\pipe\mencoder1232399239713
[win32/mencoder.exe] INFO 16:07:19.978 Attaching thread: win32/mencoder.exe
[Thread-51] DEBUG 16:07:19.993 MEncoder Sherpya-SVN-r28126-4.2.5 (C) 2000-2008 MPlayer Team
[Thread-51] DEBUG 16:07:19.993 CPU: Intel(R) Core(TM)2 Duo CPU E8400 @ 3.00GHz (Family: 6, Model: 23, Stepping: 6)
[Thread-51] DEBUG 16:07:19.993 CPUflags: Type: 6 MMX: 1 MMX2: 1 3DNow: 0 3DNow2: 0 SSE: 1 SSE2: 1
[Thread-51] DEBUG 16:07:19.993 Compiled with runtime CPU detection.
[Thread-51] DEBUG 16:07:20.009 success: format: 0 data: 0x0 - 0x17dd5374
[Thread-51] DEBUG 16:07:20.009 [mkv] Track ID 1: video (V_MPEG4/ISO/AVC), -vid 0
[Thread-51] DEBUG 16:07:20.009 [mkv] Track ID 2: audio (A_DTS), -aid 0, -alang eng
[Thread-51] DEBUG 16:07:20.009 [mkv] Track ID 3: subtitles (S_TEXT/UTF8), -sid 0, -slang eng
[Thread-51] DEBUG 16:07:20.009 [mkv] Will play video track 1.
[Thread-51] DEBUG 16:07:20.009 Matroska file format detected.
[Thread-51] DEBUG 16:07:20.009 VIDEO: [avc1] 1280x544 24bpp 23.976 fps 0.0 kbps ( 0.0 kbyte/s)
[Thread-51] DEBUG 16:07:20.009 [V] filefmt:31 fourcc:0x31637661 size:1280x544 fps:23.976 ftime:=0.0417
[Thread-51] DEBUG 16:07:20.009 ==========================================================================
[Thread-51] DEBUG 16:07:20.009 Opening audio decoder: [libdca] DTS decoding with libdca
[Thread-51] DEBUG 16:07:20.009 AUDIO: 48000 Hz, 6 ch, s16le, 1536.0 kbit/33.33% (ratio: 192000->576000)
[Thread-51] DEBUG 16:07:20.009 Selected audio codec: [dts] afm: libdca (DTS-libdca)
[Thread-51] DEBUG 16:07:20.009 ==========================================================================
[Thread-47] INFO 16:07:20.009 Result of \\.\pipe\mencoder1232399239713 : true
[Thread-51] DEBUG 16:07:20.009 PACKET SIZE: 2048 bytes, deltascr: 884
[Thread-51] DEBUG 16:07:20.009 [ass] auto-open
[Thread-51] DEBUG 16:07:20.009 [ass] Init
[Thread-51] DEBUG 16:07:20.009 ==========================================================================
[Thread-51] DEBUG 16:07:20.009 Opening video decoder: [ffmpeg] FFmpeg's libavcodec codec family
[Thread-50] DEBUG 16:07:20.009 Stream with high frequencies VQ coding
[Thread-50] DEBUG 16:07:20.009 Warning: -ass implies -keep-pts, which may cause "badly interleaved" files.
[Thread-50] DEBUG 16:07:20.009 [ass] Fontconfig disabled, only default font will be used.
[Thread-51] DEBUG 16:07:20.009 Selected video codec: [ffh264] vfm: ffmpeg (FFmpeg H.264)
[Thread-51] DEBUG 16:07:20.009 ==========================================================================
[Thread-50] DEBUG 16:07:20.009 Limiting audio preload to 0.4s.
[Thread-50] DEBUG 16:07:20.009 Increasing audio density to 4.
[Thread-51] DEBUG 16:07:20.040 Writing header...
[Thread-51] DEBUG 16:07:20.040 VDec: vo config request - 1280 x 544 (preferred colorspace: Planar YV12)
[Thread-51] DEBUG 16:07:20.040 VDec: using Planar YV12 as output csp (no 0)
[Thread-51] DEBUG 16:07:20.040 Movie-Aspect is 2.35:1 - prescaling to correct movie aspect.
[Thread-51] DEBUG 16:07:20.040 videocodec: libavcodec (1280x544 fourcc=3267706d [mpg2])
[Thread-51] DEBUG 16:07:20.040 [VE_LAVC] Using constant qscale = 1.000000 (VBR).
[Timer-1] DEBUG 16:07:20.867 Buffered Space: 2205696 bytes
[Timer-1] DEBUG 16:07:21.881 Buffered Space: 6412288 bytes
[Thread-37] INFO 16:07:22.349 Stopping process: win32/ffmpeg.exe
[Thread-37] INFO 16:07:22.349 Destroying buffer
[Timer-1] DEBUG 16:07:22.895 Buffered Space: 13381632 bytes
[Timer-1] DEBUG 16:07:23.909 Buffered Space: 19650560 bytes
[Timer-1] DEBUG 16:07:24.923 Buffered Space: 25124864 bytes
[Timer-1] DEBUG 16:07:25.937 Buffered Space: 30982144 bytes
[Thread-46] DEBUG 16:07:26.015 Wrote on socket: Content-Type: video/mpeg
[Thread-46] DEBUG 16:07:26.015 Wrote on socket: Connection: keep-alive
[Thread-46] DEBUG 16:07:26.015 Wrote on socket: Server: Windows Vista-x86-6.0 UPnP/1.0, PMS
[Thread-46] DEBUG 16:07:26.015 Wrote on socket:
[Thread-52] DEBUG 16:07:26.109 Opened handler on socket Socket[addr=/192.168.0.98,port=65245,localport=5001]
[Thread-52] DEBUG 16:07:26.109 Received on socket: GET /get/0$0$5/Test1.mkv HTTP/1.1
[Thread-52] DEBUG 16:07:26.109 Received on socket: Host: 192.168.0.7:5001
[Thread-52] DEBUG 16:07:26.109 Received on socket: User-Agent: PLAYSTATION 3
[Thread-52] DEBUG 16:07:26.109 Received on socket: Connection: Keep-Alive
[Thread-52] DEBUG 16:07:26.124 Received on socket: Accept-Encoding: identity
[Thread-52] INFO 16:07:26.124 HTTP: get/0$0$5/Test1.mkv / 0-0
[Thread-52] DEBUG 16:07:26.124 Wrote on socket: HTTP/1.1 200 OK
[Thread-52] DEBUG 16:07:26.124 Searching for objectId: 0$0$5 with children option: false
[Thread-52] DEBUG 16:07:26.124 Asked stream chunk [0-0] timeseek: 0.0 of Test1.mkv and player MEncoder
[Thread-52] DEBUG 16:07:26.124 Wrote on socket: Content-Type: video/mpeg
[Thread-52] DEBUG 16:07:26.124 Wrote on socket: Connection: keep-alive
[Thread-52] DEBUG 16:07:26.124 Wrote on socket: Server: Windows Vista-x86-6.0 UPnP/1.0, PMS
[Thread-52] DEBUG 16:07:26.124 Wrote on socket:
[Thread-52] DEBUG 16:07:26.202 Sending stream with premature end : 1114112 bytes of get/0$0$5/Test1.mkv. Reason: An existing connection was forcibly closed by the remote host
[Thread-52] DEBUG 16:07:26.202 Ready to Stop: true
[Thread-52] DEBUG 16:07:26.202 Sending stream: 1114112 bytes of get/0$0$5/Test1.mkv
[Thread-52] DEBUG 16:07:26.202 Close Connection
[Thread-53] INFO 16:07:26.904 Stopping process: win32/mencoder.exe
[Thread-53] INFO 16:07:26.904 Destroying buffer
[Thread-54] INFO 16:07:26.935 Destroying buffer
[Thread-47] DEBUG 16:07:26.935 EOF
[win32/mencoder.exe] DEBUG 16:07:26.935 EOF
[Thread-47] INFO 16:07:26.935 Disconnected pipe
[Thread-46] DEBUG 16:07:28.324 Sending stream with premature end : 1245184 bytes of get/0$0$5/Test1.mkv. Reason: An existing connection was forcibly closed by the remote host
[Thread-46] DEBUG 16:07:28.324 Sending stream: 1245184 bytes of get/0$0$5/Test1.mkv
[Thread-46] DEBUG 16:07:28.324 Close Connection
[Thread-57] DEBUG 16:07:28.324 Opened handler on socket Socket[addr=/192.168.0.98,port=65244,localport=5001]
[Thread-57] DEBUG 16:07:28.324 Received on socket: GET /get/0$0$5/Test1.mkv HTTP/1.1
[Thread-57] DEBUG 16:07:28.324 Received on socket: Host: 192.168.0.7:5001
[Thread-57] DEBUG 16:07:28.324 Received on socket: User-Agent: PLAYSTATION 3
[Thread-57] DEBUG 16:07:28.339 Received on socket: Connection: Keep-Alive
[Thread-57] DEBUG 16:07:28.339 Received on socket: Accept-Encoding: identity
[Thread-57] DEBUG 16:07:28.339 Received on socket: TimeSeekRange.dlna.org : npt=0.000-
[Thread-57] INFO 16:07:28.339 HTTP: get/0$0$5/Test1.mkv / 0-0
[Thread-57] DEBUG 16:07:28.339 Wrote on socket: HTTP/1.1 200 OK
[Thread-57] DEBUG 16:07:28.339 Searching for objectId: 0$0$5 with children option: false
[Thread-57] DEBUG 16:07:28.339 Asked stream chunk [0-0] timeseek: 0.0 of Test1.mkv and player MEncoder
[Thread-57] TRACE 16:07:28.339 Starting transcode of Test1.mkv
[Thread-57] INFO 16:07:28.339 Creating pipe \\.\pipe\mencoder1232399248339
[Thread-58] INFO 16:07:28.355 Waiting for pipe connection \\.\pipe\mencoder1232399248339
[Timer-2] DEBUG 16:07:28.355 Buffered Space: 0 bytes
[win32/mencoder.exe] INFO 16:07:28.417 Starting C:\Program Files\PS3 Media Server\win32\mencoder.exe -ss 0 -quiet E:\TVersity-E\Test1.mkv -quiet -quiet -oac lavc -of mpeg -mpegopts format=mpeg2:muxrate=500000:vbuf_size=1194:abuf_size=64 -ovc lavc -channels 6 -lavdopts debug=0:threads=2 -lavcopts autoaspect=1:vcodec=mpeg2video:acodec=ac3:abitrate=384:threads=2:keyint=1:vqscale=1:vqmin=2 -ass -nofontconfig -subcp cp1252 -alang eng,fre,jpn,ger -ass-color ffffff00 -ass-border-color 00000000 -ass-font-scale 1.0 -ass-force-style FontName=Arial,Outline=1,Shadow=1,MarginV=10 -slang eng,fre,jpn,ger -quiet -quiet -quiet -quiet -ofps 24000/1001 -quiet -quiet -af lavcresample=48000 -srate 48000 -o \\.\pipe\mencoder1232399248339
[win32/mencoder.exe] INFO 16:07:28.417 Reading pipe: \\.\pipe\mencoder1232399248339
[win32/mencoder.exe] INFO 16:07:28.417 Attaching thread: win32/mencoder.exe
[Thread-61] DEBUG 16:07:28.433 MEncoder Sherpya-SVN-r28126-4.2.5 (C) 2000-2008 MPlayer Team
[Thread-61] DEBUG 16:07:28.433 CPU: Intel(R) Core(TM)2 Duo CPU E8400 @ 3.00GHz (Family: 6, Model: 23, Stepping: 6)
[Thread-61] DEBUG 16:07:28.433 CPUflags: Type: 6 MMX: 1 MMX2: 1 3DNow: 0 3DNow2: 0 SSE: 1 SSE2: 1
[Thread-61] DEBUG 16:07:28.433 Compiled with runtime CPU detection.
[Thread-61] DEBUG 16:07:28.449 success: format: 0 data: 0x0 - 0x17dd5374
[Thread-61] DEBUG 16:07:28.449 [mkv] Track ID 1: video (V_MPEG4/ISO/AVC), -vid 0
[Thread-61] DEBUG 16:07:28.449 [mkv] Track ID 2: audio (A_DTS), -aid 0, -alang eng
[Thread-61] DEBUG 16:07:28.449 [mkv] Track ID 3: subtitles (S_TEXT/UTF8), -sid 0, -slang eng
[Thread-61] DEBUG 16:07:28.449 [mkv] Will play video track 1.
[Thread-61] DEBUG 16:07:28.449 Matroska file format detected.
[Thread-61] DEBUG 16:07:28.449 VIDEO: [avc1] 1280x544 24bpp 23.976 fps 0.0 kbps ( 0.0 kbyte/s)
[Thread-61] DEBUG 16:07:28.449 [V] filefmt:31 fourcc:0x31637661 size:1280x544 fps:23.976 ftime:=0.0417
[Thread-61] DEBUG 16:07:28.449 ==========================================================================
[Thread-61] DEBUG 16:07:28.449 Opening audio decoder: [libdca] DTS decoding with libdca
[Thread-61] DEBUG 16:07:28.449 AUDIO: 48000 Hz, 6 ch, s16le, 1536.0 kbit/33.33% (ratio: 192000->576000)
[Thread-61] DEBUG 16:07:28.449 Selected audio codec: [dts] afm: libdca (DTS-libdca)
[Thread-61] DEBUG 16:07:28.449 ==========================================================================
[Thread-61] DEBUG 16:07:28.449 PACKET SIZE: 2048 bytes, deltascr: 884
[Thread-58] INFO 16:07:28.449 Result of \\.\pipe\mencoder1232399248339 : true
[Thread-61] DEBUG 16:07:28.449 [ass] auto-open
[Thread-60] DEBUG 16:07:28.449 Stream with high frequencies VQ coding
[Thread-60] DEBUG 16:07:28.449 Warning: -ass implies -keep-pts, which may cause "badly interleaved" files.
[Thread-61] DEBUG 16:07:28.449 [ass] Init
[Thread-61] DEBUG 16:07:28.449 ==========================================================================
[Thread-60] DEBUG 16:07:28.449 [ass] Fontconfig disabled, only default font will be used.
[Thread-61] DEBUG 16:07:28.449 Opening video decoder: [ffmpeg] FFmpeg's libavcodec codec family
[Thread-61] DEBUG 16:07:28.449 Selected video codec: [ffh264] vfm: ffmpeg (FFmpeg H.264)
[Thread-61] DEBUG 16:07:28.449 ==========================================================================
[Thread-60] DEBUG 16:07:28.449 Limiting audio preload to 0.4s.
[Thread-60] DEBUG 16:07:28.449 Increasing audio density to 4.
[Thread-61] DEBUG 16:07:28.495 Writing header...
[Thread-61] DEBUG 16:07:28.495 VDec: vo config request - 1280 x 544 (preferred colorspace: Planar YV12)
[Thread-61] DEBUG 16:07:28.495 VDec: using Planar YV12 as output csp (no 0)
[Thread-61] DEBUG 16:07:28.495 Movie-Aspect is 2.35:1 - prescaling to correct movie aspect.
[Thread-61] DEBUG 16:07:28.495 videocodec: libavcodec (1280x544 fourcc=3267706d [mpg2])
[Thread-61] DEBUG 16:07:28.495 [VE_LAVC] Using constant qscale = 1.000000 (VBR).
[Thread-56] INFO 16:07:29.026 Destroying buffer
[Thread-55] INFO 16:07:29.057 Destroying buffer
[Timer-2] DEBUG 16:07:29.369 Buffered Space: 2045952 bytes
[Timer-2] DEBUG 16:07:30.383 Buffered Space: 6148096 bytes
[Timer-2] DEBUG 16:07:31.397 Buffered Space: 13381632 bytes
[Timer-2] DEBUG 16:07:32.411 Buffered Space: 19652608 bytes
[Timer-2] DEBUG 16:07:33.425 Buffered Space: 25376768 bytes
[Timer-2] DEBUG 16:07:34.439 Buffered Space: 31567872 bytes
[Thread-57] DEBUG 16:07:34.486 Wrote on socket: Content-Type: video/mpeg
[Thread-57] DEBUG 16:07:34.486 Wrote on socket: Connection: keep-alive
[Thread-57] DEBUG 16:07:34.486 Wrote on socket: Server: Windows Vista-x86-6.0 UPnP/1.0, PMS
[Thread-57] DEBUG 16:07:34.486 Wrote on socket:
[Timer-2] DEBUG 16:07:35.453 Buffered Space: 27850752 bytes
[Timer-2] DEBUG 16:07:36.467 Buffered Space: 19972096 bytes
[Thread-60] DEBUG 16:07:36.857 [h264 @ 01C22830]Cannot parallelize deblocking type 1, decoding such frames in sequential order
[Thread-60] DEBUG 16:07:36.857 [ass] PlayResX undefined, setting 678.
[Timer-2] DEBUG 16:07:37.481 Buffered Space: 10743808 bytes
[Timer-2] DEBUG 16:07:38.495 Buffered Space: 2859008 bytes
[Thread-57] DEBUG 16:07:38.729 Suspend Read: readCount=48824320 / writeCount=49776640
[Thread-58] DEBUG 16:07:38.791 freeMemory: 41470784
[Thread-58] DEBUG 16:07:38.791 totalMemory: 96235520
[Thread-58] DEBUG 16:07:38.791 maxMemory: 799145984
[Thread-58] DEBUG 16:07:38.791 Extending buffer to 419430400
[Thread-58] DEBUG 16:07:39.150 Done extending
[Thread-57] DEBUG 16:07:39.244 Resume Read: readCount=48824320 / writeCount=50757632
[Thread-57] DEBUG 16:07:39.353 Suspend Read: readCount=50266112 / writeCount=51204096
[Timer-2] DEBUG 16:07:39.509 Buffered Space: 1521664 bytes
[Thread-57] DEBUG 16:07:39.868 Resume Read: readCount=50266112 / writeCount=53084160
[Thread-57] DEBUG 16:07:40.102 Suspend Read: readCount=53084160 / writeCount=54020096
[Timer-2] DEBUG 16:07:40.523 Buffered Space: 2459648 bytes
[Thread-57] DEBUG 16:07:40.617 Resume Read: readCount=53084160 / writeCount=55924736
[Thread-57] DEBUG 16:07:40.851 Suspend Read: readCount=55836672 / writeCount=56817664
[Thread-57] DEBUG 16:07:41.365 Resume Read: readCount=55836672 / writeCount=58912768
[Timer-2] DEBUG 16:07:41.537 Buffered Space: 1617920 bytes
[Thread-57] DEBUG 16:07:41.615 Suspend Read: readCount=58851328 / writeCount=59834368
[Thread-57] DEBUG 16:07:42.130 Resume Read: readCount=58851328 / writeCount=61804544
[Thread-57] DEBUG 16:07:42.379 Suspend Read: readCount=61931520 / writeCount=62894080
[Timer-2] DEBUG 16:07:42.551 Buffered Space: 1566720 bytes
[Thread-57] DEBUG 16:07:42.894 Resume Read: readCount=61931520 / writeCount=65114112
[Thread-57] DEBUG 16:07:43.175 Suspend Read: readCount=65208320 / writeCount=66181120
[Timer-2] DEBUG 16:07:43.565 Buffered Space: 2762752 bytes
[Thread-57] DEBUG 16:07:43.690 Resume Read: readCount=65208320 / writeCount=68679680
[Thread-57] DEBUG 16:07:44.064 Suspend Read: readCount=69533696 / writeCount=70479872
[Thread-57] DEBUG 16:07:44.579 Resume Read: readCount=69533696 / writeCount=73592832
[Timer-2] DEBUG 16:07:44.579 Buffered Space: 3928064 bytes
[Thread-57] DEBUG 16:07:45.063 Suspend Read: readCount=75104256 / writeCount=76066816
[Thread-57] DEBUG 16:07:45.577 Resume Read: readCount=75104256 / writeCount=78555136
[Timer-2] DEBUG 16:07:45.593 Buffered Space: 3252224 bytes
[Thread-57] DEBUG 16:07:45.952 Suspend Read: readCount=79560704 / writeCount=80541696
[Thread-57] DEBUG 16:07:46.467 Resume Read: readCount=79560704 / writeCount=82952192
[Timer-2] DEBUG 16:07:46.607 Buffered Space: 2445312 bytes
[Thread-57] DEBUG 16:07:46.810 Suspend Read: readCount=83558400 / writeCount=84516864
[Thread-57] DEBUG 16:07:47.325 Resume Read: readCount=83558400 / writeCount=87009280
[Timer-2] DEBUG 16:07:47.621 Buffered Space: 1748992 bytes
[Thread-57] DEBUG 16:07:47.730 Suspend Read: readCount=88342528 / writeCount=89327616
[Thread-57] DEBUG 16:07:48.245 Resume Read: readCount=88342528 / writeCount=93349888
[Timer-2] DEBUG 16:07:48.635 Buffered Space: 3743744 bytes
[Thread-57] DEBUG 16:07:49.290 Suspend Read: readCount=100335616 / writeCount=101292032
[Timer-2] DEBUG 16:07:49.649 Buffered Space: 3293184 bytes
[Thread-57] DEBUG 16:07:49.805 Resume Read: readCount=100335616 / writeCount=104515584
[Thread-57] DEBUG 16:07:50.460 Suspend Read: readCount=107937792 / writeCount=108904448
[Timer-2] DEBUG 16:07:50.663 Buffered Space: 2387968 bytes
[Thread-57] DEBUG 16:07:50.975 Resume Read: readCount=107937792 / writeCount=112795648
[Timer-2] DEBUG 16:07:51.677 Buffered Space: 1200128 bytes
[Thread-57] DEBUG 16:07:51.693 Suspend Read: readCount=116326400 / writeCount=117264384
[Thread-57] DEBUG 16:07:52.207 Resume Read: readCount=116326400 / writeCount=120571904
[Timer-2] DEBUG 16:07:52.691 Buffered Space: 1789952 bytes
[Thread-57] DEBUG 16:07:52.831 Suspend Read: readCount=123600896 / writeCount=124598272
[Thread-57] DEBUG 16:07:53.346 Resume Read: readCount=123600896 / writeCount=127670272
[Timer-2] DEBUG 16:07:53.705 Buffered Space: 1495040 bytes
[Thread-57] DEBUG 16:07:53.767 Suspend Read: readCount=128647168 / writeCount=129628160
[Thread-57] DEBUG 16:07:54.282 Resume Read: readCount=128647168 / writeCount=132030464
[Thread-57] DEBUG 16:07:54.594 Suspend Read: readCount=132317184 / writeCount=133302272
[Timer-2] DEBUG 16:07:54.719 Buffered Space: 1503232 bytes
[Thread-57] DEBUG 16:07:55.109 Resume Read: readCount=132317184 / writeCount=135378944
[Thread-57] DEBUG 16:07:55.359 Suspend Read: readCount=135266304 / writeCount=136208384
[Timer-2] DEBUG 16:07:55.733 Buffered Space: 2420736 bytes
[Thread-57] DEBUG 16:07:55.873 Resume Read: readCount=135266304 / writeCount=138297344
[Thread-57] DEBUG 16:07:56.139 Suspend Read: readCount=138477568 / writeCount=139458560
[Thread-57] DEBUG 16:07:56.653 Resume Read: readCount=138477568 / writeCount=141672448
[Timer-2] DEBUG 16:07:56.747 Buffered Space: 2570240 bytes
[Thread-57] DEBUG 16:07:56.965 Suspend Read: readCount=142278656 / writeCount=143257600
[Thread-57] DEBUG 16:07:57.480 Resume Read: readCount=142278656 / writeCount=145367040
[Timer-2] DEBUG 16:07:57.761 Buffered Space: 1030144 bytes
[Thread-57] DEBUG 16:07:57.761 Suspend Read: readCount=145620992 / writeCount=146585600
[Thread-57] DEBUG 16:07:58.276 Resume Read: readCount=145620992 / writeCount=148731904
[Thread-57] DEBUG 16:07:58.525 Suspend Read: readCount=148635648 / writeCount=149633024
[Timer-2] DEBUG 16:07:58.775 Buffered Space: 2037760 bytes
[Thread-57] DEBUG 16:07:59.040 Resume Read: readCount=148635648 / writeCount=151908352
[Thread-57] DEBUG 16:07:59.321 Suspend Read: readCount=152043520 / writeCount=153006080
[Timer-2] DEBUG 16:07:59.789 Buffered Space: 2748416 bytes
[Thread-57] DEBUG 16:07:59.836 Resume Read: readCount=152043520 / writeCount=154892288
[Thread-57] DEBUG 16:08:00.023 Suspend Read: readCount=154337280 / writeCount=155328512
[Thread-57] DEBUG 16:08:00.538 Resume Read: readCount=154337280 / writeCount=156516352
[Thread-57] DEBUG 16:08:00.678 Suspend Read: readCount=156041216 / writeCount=156993536
[Timer-2] DEBUG 16:08:00.803 Buffered Space: 1306624 bytes
[Thread-57] DEBUG 16:08:01.193 Resume Read: readCount=156041216 / writeCount=158789632
[Thread-57] DEBUG 16:08:01.427 Suspend Read: readCount=158793728 / writeCount=159778816
[Timer-2] DEBUG 16:08:01.817 Buffered Space: 2807808 bytes
[Thread-57] DEBUG 16:08:01.942 Resume Read: readCount=158793728 / writeCount=162295808
[Thread-57] DEBUG 16:08:02.316 Suspend Read: readCount=163184640 / writeCount=164134912
[Timer-2] DEBUG 16:08:02.831 Buffered Space: 3375104 bytes
[Thread-57] DEBUG 16:08:02.831 Resume Read: readCount=163184640 / writeCount=166559744
[Thread-57] DEBUG 16:08:03.112 Suspend Read: readCount=166592512 / writeCount=167550976
[Thread-57] DEBUG 16:08:03.627 Resume Read: readCount=166592512 / writeCount=168742912
[Thread-57] DEBUG 16:08:03.736 Suspend Read: readCount=168034304 / writeCount=169029632
[Timer-2] DEBUG 16:08:03.845 Buffered Space: 1253376 bytes
[Thread-57] DEBUG 16:08:04.251 Resume Read: readCount=168034304 / writeCount=170575872
[Thread-57] DEBUG 16:08:04.422 Suspend Read: readCount=170131456 / writeCount=171102208
[Timer-2] DEBUG 16:08:04.859 Buffered Space: 2709504 bytes
[Thread-57] DEBUG 16:08:04.937 Resume Read: readCount=170131456 / writeCount=173197312
[Thread-57] DEBUG 16:08:05.218 Suspend Read: readCount=173473792 / writeCount=174444544
[Thread-57] DEBUG 16:08:05.733 Resume Read: readCount=173473792 / writeCount=176695296
[Timer-2] DEBUG 16:08:05.873 Buffered Space: 1923072 bytes
[Thread-57] DEBUG 16:08:05.982 Suspend Read: readCount=176422912 / writeCount=177393664
[Thread-57] DEBUG 16:08:06.497 Resume Read: readCount=176422912 / writeCount=179642368
[Thread-57] DEBUG 16:08:06.825 Suspend Read: readCount=180355072 / writeCount=181293056
[Timer-2] DEBUG 16:08:06.887 Buffered Space: 1239040 bytes
[Thread-57] DEBUG 16:08:07.339 Resume Read: readCount=180355072 / writeCount=184244224
[Thread-57] DEBUG 16:08:07.807 Suspend Read: readCount=185794560 / writeCount=186771456
[Timer-2] DEBUG 16:08:07.901 Buffered Space: 1492992 bytes
[Thread-57] DEBUG 16:08:08.322 Resume Read: readCount=185794560 / writeCount=189634560
[Thread-57] DEBUG 16:08:08.712 Suspend Read: readCount=190447616 / writeCount=191447040
[Timer-2] DEBUG 16:08:08.915 Buffered Space: 1898496 bytes
[Thread-57] DEBUG 16:08:09.227 Resume Read: readCount=190447616 / writeCount=193763328
[Thread-57] DEBUG 16:08:09.523 Suspend Read: readCount=194052096 / writeCount=195004416
[Timer-2] DEBUG 16:08:09.929 Buffered Space: 2734080 bytes
[Thread-57] DEBUG 16:08:10.038 Resume Read: readCount=194052096 / writeCount=197257216
[Thread-57] DEBUG 16:08:10.350 Suspend Read: readCount=197787648 / writeCount=198780928
[Thread-57] DEBUG 16:08:10.865 Resume Read: readCount=197787648 / writeCount=201365504
[Timer-2] DEBUG 16:08:10.943 Buffered Space: 2942976 bytes
[Thread-57] DEBUG 16:08:11.286 Suspend Read: readCount=202768384 / writeCount=203753472
[Thread-57] DEBUG 16:08:11.801 Resume Read: readCount=202768384 / writeCount=206692352
[Timer-2] DEBUG 16:08:11.957 Buffered Space: 2537472 bytes
[Thread-57] DEBUG 16:08:12.160 Suspend Read: readCount=206962688 / writeCount=207921152
[Thread-57] DEBUG 16:08:12.675 Resume Read: readCount=206962688 / writeCount=210612224
[Timer-2] DEBUG 16:08:12.971 Buffered Space: 2586624 bytes
[Thread-57] DEBUG 16:08:13.517 Suspend Read: readCount=216793088 / writeCount=217786368
[Timer-2] DEBUG 16:08:13.985 Buffered Space: 5277696 bytes
[Thread-57] DEBUG 16:08:14.032 Resume Read: readCount=216793088 / writeCount=222216192
[Thread-57] DEBUG 16:08:14.547 Suspend Read: readCount=222822400 / writeCount=223801344
[Timer-2] DEBUG 16:08:14.999 Buffered Space: 2803712 bytes
[Thread-57] DEBUG 16:08:15.061 Resume Read: readCount=222822400 / writeCount=225976320
[Thread-57] DEBUG 16:08:15.311 Suspend Read: readCount=225837056 / writeCount=226772992
[Thread-57] DEBUG 16:08:15.826 Resume Read: readCount=225837056 / writeCount=229179392
[Timer-2] DEBUG 16:08:16.013 Buffered Space: 2603008 bytes
[Thread-57] DEBUG 16:08:16.419 Suspend Read: readCount=232652800 / writeCount=233611264
[Thread-57] DEBUG 16:08:16.933 Resume Read: readCount=232652800 / writeCount=238389248
[Timer-2] DEBUG 16:08:17.027 Buffered Space: 5130240 bytes
[Timer-2] DEBUG 16:08:18.041 Buffered Space: 1560576 bytes
[Thread-57] DEBUG 16:08:18.181 Suspend Read: readCount=246939648 / writeCount=247926784
[Thread-57] DEBUG 16:08:18.696 Resume Read: readCount=246939648 / writeCount=251815936
[Timer-2] DEBUG 16:08:19.055 Buffered Space: 3328000 bytes
[Thread-57] DEBUG 16:08:19.570 Suspend Read: readCount=257032192 / writeCount=258031616
[Timer-2] DEBUG 16:08:20.069 Buffered Space: 3575808 bytes
[Thread-57] DEBUG 16:08:20.085 Resume Read: readCount=257032192 / writeCount=260610048
[Thread-57] DEBUG 16:08:20.397 Suspend Read: readCount=260702208 / writeCount=261691392
[Thread-57] DEBUG 16:08:20.911 Resume Read: readCount=260702208 / writeCount=263438336
[Timer-2] DEBUG 16:08:21.083 Buffered Space: 1234944 bytes
[Thread-57] DEBUG 16:08:21.099 Suspend Read: readCount=263061504 / writeCount=264022016
[Thread-57] DEBUG 16:08:21.613 Resume Read: readCount=263061504 / writeCount=265639936
[Thread-57] DEBUG 16:08:21.785 Suspend Read: readCount=265158656 / writeCount=266110976
[Timer-2] DEBUG 16:08:22.097 Buffered Space: 1949696 bytes
[Thread-57] DEBUG 16:08:22.300 Resume Read: readCount=265158656 / writeCount=267741184
[Thread-57] DEBUG 16:08:22.471 Suspend Read: readCount=267321344 / writeCount=268310528
[Thread-57] DEBUG 16:08:22.986 Resume Read: readCount=267321344 / writeCount=269752320
[Timer-2] DEBUG 16:08:23.111 Buffered Space: 1298432 bytes
[Thread-57] DEBUG 16:08:23.142 Suspend Read: readCount=269221888 / writeCount=270182400
[Thread-57] DEBUG 16:08:23.657 Resume Read: readCount=269221888 / writeCount=271929344
[Thread-57] DEBUG 16:08:23.875 Suspend Read: readCount=271777792 / writeCount=272728064
[Timer-2] DEBUG 16:08:24.125 Buffered Space: 2072576 bytes
[Thread-57] DEBUG 16:08:24.390 Resume Read: readCount=271777792 / writeCount=275007488
[Thread-57] DEBUG 16:08:24.671 Suspend Read: readCount=275251200 / writeCount=276226048
[Timer-2] DEBUG 16:08:25.139 Buffered Space: 3184640 bytes
[Thread-57] DEBUG 16:08:25.186 Resume Read: readCount=275251200 / writeCount=278626304
[Thread-57] DEBUG 16:08:25.513 Suspend Read: readCount=279117824 / writeCount=280068096
[Thread-57] DEBUG 16:08:26.028 Resume Read: readCount=279117824 / writeCount=282365952
[Timer-2] DEBUG 16:08:26.153 Buffered Space: 2074624 bytes
[Thread-57] DEBUG 16:08:26.278 Suspend Read: readCount=282132480 / writeCount=283131904
[Thread-57] DEBUG 16:08:26.793 Resume Read: readCount=282132480 / writeCount=284917760
[Thread-57] DEBUG 16:08:26.995 Suspend Read: readCount=284688384 / writeCount=285634560
[Timer-2] DEBUG 16:08:27.167 Buffered Space: 1533952 bytes
[Thread-57] DEBUG 16:08:27.510 Resume Read: readCount=284688384 / writeCount=287604736
[Timer-2] DEBUG 16:08:28.181 Buffered Space: 3831808 bytes
[Timer-2] DEBUG 16:08:29.195 Buffered Space: 7737344 bytes
[Timer-2] DEBUG 16:08:30.209 Buffered Space: 13047808 bytes
[Timer-2] DEBUG 16:08:31.223 Buffered Space: 19372032 bytes
[Timer-2] DEBUG 16:08:32.237 Buffered Space: 25581568 bytes
[Timer-2] DEBUG 16:08:33.251 Buffered Space: 31811584 bytes
[Timer-2] DEBUG 16:08:34.265 Buffered Space: 37806080 bytes
[Timer-2] DEBUG 16:08:35.279 Buffered Space: 43907072 bytes
[Timer-2] DEBUG 16:08:36.293 Buffered Space: 49790976 bytes
[Timer-2] DEBUG 16:08:37.307 Buffered Space: 55535616 bytes
