search

google-code-export / red5

Automatically exported from code.google.com/p/red5
0 stars 0 forks source link

When delayed.write=true Red5 creates video recordings with almost 0 video keyframes #500

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
0. make sure fileconsumer.delayed.write=true in conf/red5.properties
1. Record a 30 seconds to 1 minute 640x480 or higher video
2. To make sure we're not loosing any buffered data, use a recorder that waits 
for the video data buffered on the client to upload/stream to the media server 
(HDFVR, free trial here: http://hdfvr.com/trial-request/free-trial) when 
"stopping" the recording
3. The video will contain very few keyframes, 1-4 instead of 1/second.

With delayed.write=false the videos are OK up to a point when the video gets 
stuck and the sound continues. This is caused by Flash player buffering the 
video data and sending only the audio data.

delayed.write=true should be the answer (it's the default value) however when 
enabling it the videos produced have sound but only 1 or 2 frames of video.

This leads me to believe that the queueThreshold mechanism in
main\java\org\red5\server\stream\consumer\FileConsumer.java is flawed.

Putting the delayed.write=true .flv file (the one with only 2 frames) through 
yamdi (flv metadata injector) confirms that there are only 2 keyframes in a 46 
seconds long file.

<keyframes>
<times>
<value id="0">0.01</value>
<value id="1">6.79</value>
</times>
<filepositions>
<value id="0">1195</value>
<value id="1">325246</value>
</filepositions>
</keyframes>
<duration>48.65</duration>

When recording using (delayed.write=false) this is how they keyframe data looks:
<keyframes>
<times>
<value id="0">0.03</value>
<value id="1">0.66</value>
<value id="2">1.22</value>
<value id="3">1.75</value>
<value id="4">2.30</value>
<value id="5">2.84</value>
<value id="6">3.38</value>
<value id="7">3.91</value>
<value id="8">4.43</value>
<value id="9">5.04</value>
<value id="10">5.59</value>
<value id="11">6.14</value>
<value id="12">6.70</value>
<value id="13">7.26</value>
<value id="14">7.84</value>
<value id="15">8.38</value>
<value id="16">8.98</value>
....

Increasing the fileconsumer.queue.size from it's default 21 to 21000 did not 
help.

I have uploaded the above mentioned 640x480 .flv file and it's meta file to
http://107.170.103.58/videoStream_1398696826803_39.flv
http://107.170.103.58/videoStream_1398696826803_39.flv.meta

Original issue reported on code.google.com by naicuoct...@gmail.com on 29 Apr 2014 at 10:57

GoogleCodeExporter commented 9 years ago 
The issue has been replicated with Red5 1.0.2.

Original comment by naicuoct...@gmail.com on 29 Apr 2014 at 10:59

GoogleCodeExporter commented 9 years ago 
I have activated logging on the 
org\red5\server\stream\consumer\FileConsumer.java class by adding 

  <logger name="org.red5.server.stream.consumer.FileConsumer">
    <level value="ALL"/>
  </logger>

to conf/logback.xml .

I then recorded a 45seconds video file. 
For the 1st half I just pointed the webcam at the wall => a 1.0-1.2Mbit/s 
video. 
At about 23 seconds in I added movement to the mix => 2-3Mbits/s of data. This 
was more than my upload bandwidth could support so immediately Flash Player 
started prioritizing audio.

The prioritization of audio is visible from the FileConsumer log. if for the 
1st 20 seconds the ratio is about 1:1 for audio and video messages.In most of 
the second half the ratio is about 3-4 audio messages for every video message. 
The last part is comprised only of video messages . My recorder empties the 
content of the client buffer before closing the connection/stream and it seems 
it's full of video data. This was in line with my expectations.

What surprised me was that the Queue length barely grows and never over 50 even 
though my fileconsumer.queue.size=21000.

2014-04-29 07:26:03,180 [Red5_Scheduler_Worker-6] DEBUG 
o.r.s.stream.consumer.FileConsumer - Data type: 8 timestamp: 30535
2014-04-29 07:26:03,180 [Red5_Scheduler_Worker-6] TRACE 
o.r.s.stream.consumer.FileConsumer - Not FlexStreamSend type
2014-04-29 07:26:03,180 [Red5_Scheduler_Worker-6] DEBUG 
o.r.s.stream.consumer.FileConsumer - Stream data, body saved. Data type: 8 
class type: org.red5.server.net.rtmp.event.AudioData
2014-04-29 07:26:03,180 [Red5_Scheduler_Worker-6] DEBUG 
o.r.s.stream.consumer.FileConsumer - Data type: 8 timestamp: 30581
2014-04-29 07:26:03,180 [Red5_Scheduler_Worker-6] TRACE 
o.r.s.stream.consumer.FileConsumer - Not FlexStreamSend type
2014-04-29 07:26:03,180 [Red5_Scheduler_Worker-6] DEBUG 
o.r.s.stream.consumer.FileConsumer - Stream data, body saved. Data type: 8 
class type: org.red5.server.net.rtmp.event.AudioData
2014-04-29 07:26:03,181 [Red5_Scheduler_Worker-6] DEBUG 
o.r.s.stream.consumer.FileConsumer - Data type: 9 timestamp: 27348
2014-04-29 07:26:03,181 [Red5_Scheduler_Worker-6] TRACE 
o.r.s.stream.consumer.FileConsumer - Not FlexStreamSend type
2014-04-29 07:26:03,181 [Red5_Scheduler_Worker-6] DEBUG 
o.r.s.stream.consumer.FileConsumer - Stream data, body saved. Data type: 9 
class type: org.red5.server.net.rtmp.event.VideoData
2014-04-29 07:26:03,181 [Red5_Scheduler_Worker-6] DEBUG 
o.r.s.stream.consumer.FileConsumer - Creating data slice up until timestamp 
27348.
2014-04-29 07:26:03,181 [Red5_Scheduler_Worker-6] TRACE 
o.r.s.stream.consumer.FileConsumer - Queue length: 50
2014-04-29 07:26:03,181 [Red5_Scheduler_Worker-6] TRACE 
o.r.s.stream.consumer.FileConsumer - Queue length (after removal): 48
2014-04-29 07:26:03,181 [Red5_Scheduler_Worker-6] DEBUG 
o.r.s.stream.consumer.FileConsumer - Write future result (expect null): null
2014-04-29 07:26:03,181 [FileConsumerExecutor-1] TRACE 
o.r.s.stream.consumer.FileConsumer - Spawning queue writer thread
2014-04-29 07:26:03,181 [FileConsumerExecutor-1] DEBUG 
o.r.s.stream.consumer.FileConsumer - Write - timestamp: 28351 type: 8

( The entire log si at  
http://pastebin.aquilenet.fr/?da504bfddc0f7221#MNyuWzLygl0nXDkihZPIVnmXpWTmd/pvb
RawJbThKEo= )

I believe the reason is this line of code:
if (msg instanceof VideoData) {
    writeQueuedDataSlice(createTimestampLimitedSlice(msg.getTimestamp()));
} else if (queueThreshold >= 0 && queueSize >= queueThreshold) {
    writeQueuedDataSlice(createFixedLengthSlice(queueThreshold / (100 / percentage)));
}

Every time a VideoData msg kicks in the queueSize is ignored and part of it is 
written to disk thus it never has a chance to grow in size and sort the packets.

The .meta file and metadata extracted using ymdi shows keyframes only in the 
1st part (the low bitrate part) of the 45 second video:
<?xml version="1.0" encoding="UTF-8"?>
<FrameMetadata audioOnly="false" duration="46133" modified="1398770782000">
    <KeyFrame position="296" timestamp="0"/>
    <KeyFrame position="95174" timestamp="522"/>
    <KeyFrame position="176939" timestamp="1015"/>
    <KeyFrame position="254115" timestamp="1543"/>
    <KeyFrame position="323827" timestamp="2047"/>
    <KeyFrame position="414126" timestamp="2584"/>
    <KeyFrame position="487913" timestamp="3085"/>
    <KeyFrame position="566341" timestamp="3608"/>
    <KeyFrame position="652646" timestamp="4126"/>
    <KeyFrame position="729640" timestamp="4617"/>
    <KeyFrame position="801604" timestamp="5143"/>
    <KeyFrame position="879746" timestamp="5642"/>
    <KeyFrame position="956177" timestamp="6183"/>
    <KeyFrame position="1034337" timestamp="6677"/>
    <KeyFrame position="1111544" timestamp="7210"/>
    <KeyFrame position="1188328" timestamp="7719"/>
    <KeyFrame position="1277927" timestamp="8210"/>
    <KeyFrame position="1357113" timestamp="8743"/>
    <KeyFrame position="1433907" timestamp="9235"/>
    <KeyFrame position="1520341" timestamp="9783"/>
    <KeyFrame position="1599936" timestamp="10286"/>
    <KeyFrame position="1677898" timestamp="10812"/>
    <KeyFrame position="1756244" timestamp="11319"/>
    <KeyFrame position="1845468" timestamp="11823"/>
    <KeyFrame position="1912589" timestamp="12345"/>
    <KeyFrame position="1982736" timestamp="12849"/>
    <KeyFrame position="2054526" timestamp="13376"/>
    <KeyFrame position="2138280" timestamp="13877"/>
    <KeyFrame position="2205050" timestamp="14405"/>
    <KeyFrame position="2286936" timestamp="14926"/>
    <KeyFrame position="2380470" timestamp="15414"/>
    <KeyFrame position="2461407" timestamp="15937"/>
    <KeyFrame position="2530624" timestamp="16444"/>
    <KeyFrame position="2605275" timestamp="16977"/>
    <KeyFrame position="2696153" timestamp="17479"/>
    <KeyFrame position="2767288" timestamp="18005"/>
    <KeyFrame position="2839005" timestamp="18513"/>
    <KeyFrame position="2915718" timestamp="19017"/>
    <KeyFrame position="2986571" timestamp="19550"/>
    <KeyFrame position="3075008" timestamp="20041"/>
    <KeyFrame position="3250870" timestamp="20589"/>
    <KeyFrame position="3336657" timestamp="21086"/>
    <KeyFrame position="3404095" timestamp="21612"/>
    <KeyFrame position="3475788" timestamp="22127"/>
    <KeyFrame position="3600533" timestamp="22612"/>
    <KeyFrame position="3825407" timestamp="23153"/>
    <KeyFrame position="3991738" timestamp="23641"/>
</FrameMetadata>

I tried testing some changes but atm I can not compile Red5 (see my other 
thread).

Original comment by naicuoct...@gmail.com on 29 Apr 2014 at 1:04

GoogleCodeExporter commented 9 years ago 
[deleted comment]
GoogleCodeExporter commented 9 years ago 
In light of a better analysis I have to correct a previous statement:

>In most of the second half the ratio is about 3-4 audio messages for every 
video message.
The ratio is the roughly the same but audio and video packets do not come in 
pairs anymore but more randomly.

In addition, in the same part of the recording, the video packets are late by a 
few seconds:

2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] DEBUG 
o.r.s.stream.consumer.FileConsumer - Data type: 8 timestamp: 46555
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] TRACE 
o.r.s.stream.consumer.FileConsumer - Not FlexStreamSend type
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] DEBUG 
o.r.s.stream.consumer.FileConsumer - Stream data, body saved. Data type: 8 
class type: org.red5.server.net.rtmp.event.AudioData
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] DEBUG 
o.r.s.stream.consumer.FileConsumer - Data type: 8 timestamp: 46602
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] TRACE 
o.r.s.stream.consumer.FileConsumer - Not FlexStreamSend type
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] DEBUG 
o.r.s.stream.consumer.FileConsumer - Stream data, body saved. Data type: 8 
class type: org.red5.server.net.rtmp.event.AudioData
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] DEBUG 
o.r.s.stream.consumer.FileConsumer - Data type: 9 timestamp: 43379
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] TRACE 
o.r.s.stream.consumer.FileConsumer - Not FlexStreamSend type
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] DEBUG 
o.r.s.stream.consumer.FileConsumer - Stream data, body saved. Data type: 9 
class type: org.red5.server.net.rtmp.event.VideoData
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] DEBUG 
o.r.s.stream.consumer.FileConsumer - Creating data slice up until timestamp 
43379.
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] TRACE 
o.r.s.stream.consumer.FileConsumer - Queue length: 10
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] TRACE 
o.r.s.stream.consumer.FileConsumer - Queue length (after removal): 8
2014-04-29 07:26:21,130 [Red5_Scheduler_Worker-32] DEBUG 
o.r.s.stream.consumer.FileConsumer - Write future result (expect null): null
2014-04-29 07:26:21,130 [FileConsumerExecutor-1] TRACE 
o.r.s.stream.consumer.FileConsumer - Spawning queue writer thread

The audio packets in the log above have timestamps around the 45.5 seconds mark 
while the video packet (data type 9) has a timestamp of 43.3 .

The last part of the log is filled only with video packets. 2-3 seconds worth 
of them. The video packets are catching up.

Original comment by naicuoct...@gmail.com on 29 Apr 2014 at 1:23

GoogleCodeExporter commented 9 years ago 
I've tested your patch and committed it to git; thank you

Original comment by mondain on 30 Apr 2014 at 3:08