6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Mon Dec 08, 2014 5:45 pm

Sorry another request

Code: Select all

uname -a
to give the kernel version
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Mon Dec 08, 2014 5:47 pm

You can request nearly anything! ;)

it gives: Linux raspberrypi 3.12.28+ #709 PREEMT Mon Sep 8 15:28:00 BST 2014 armv6l GNU/Linux

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Tue Dec 09, 2014 10:51 am

6by9 wrote:The main camera crystal is running at 25MHz instead of the intended 24.8MHz, so that will run 0.81% fast (ie too many frames per time interval) - not a big enough difference to explain your diffs.

All frames are timestamped, but as raspivid doesn't write to a container and the raw H264 bitstream doesn't have timestamps, you don't see it.
I'd suggest you do a couple of your own tests:
- checkout your own copy of the userland tree (git clone https://github.com/raspberrypi/userland.git)
- cd userland
- edit raspivid.c (nano host_applications/linux/apps/raspicam/RaspiVid.c) and add code in encoder_buffer_callback to print out buffer->pts.
- compile it (./buildme)
- run your new raspivid (it will have been installed to the normal /opt/vc directory by buildme) and see what the timestamps are.
If there are jumps of 80ms between some buffers then your SD card isn't keeping up. Retest with streaming to /dev/nul to confirm that the timestamps are then even.
I have followed your instructions.

At the end of the function encoder_buffer_callback() I added

Code: Select all

FILE *outputfile;
outputfile = fopen("/home/pi/userland/build/bin/output_raspivid.txt","a");
fprintf(outputfile,"%" PRId64 "\n", buffer->pts);
fclose(outputfile);
When I then record a 2 second video I get in output_raspivid.txt:

Code: Select all

0
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
-9223372036854775808
Have you or anyone an idea what I could still be wrong?

6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Tue Dec 09, 2014 11:37 am

el_cid wrote:I have followed your instructions.

At the end of the function encoder_buffer_callback() I added

Code: Select all

FILE *outputfile;
outputfile = fopen("/home/pi/userland/build/bin/output_raspivid.txt","a");
fprintf(outputfile,"%" PRId64 "\n", buffer->pts);
fclose(outputfile);
When I then record a 2 second video I get in output_raspivid.txt:

Code: Select all

0
-9223372036854775808
...
Have you or anyone an idea what I could still be wrong?
-9223372036854775808 = 8000000000000000 = 1<<63 = MMAL_TIME_UNKNOWN (see https://github.com/raspberrypi/userland ... ypes.h#L88) Bum! Either something odd is going on, or we should be looking at dts.
I will try to spin up my own Pi tonight to have a look at this. The frames should be timestamped sensibly (with the GPU STC).

I can't remember what the default buffer size is. If it is smaller than the frame size, then the first buffer would come through with the correct timestamp (and flags having MMAL_BUFFER_HEADER_FLAG_FRAME_START set), and subsequent buffers in the same frame would get MMAL_TIME_UNKNOWN until the last buffer in the frame would also have the MMAL_BUFFER_HEADER_FLAG_FRAME_END flag set. That would explain seeing some buffers with TIME_UNKNOWN, but not all of them.
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Tue Dec 09, 2014 1:26 pm

6by9 wrote: -9223372036854775808 = 8000000000000000 = 1<<63 = MMAL_TIME_UNKNOWN (see https://github.com/raspberrypi/userland ... ypes.h#L88) Bum! Either something odd is going on, or we should be looking at dts.
I will try to spin up my own Pi tonight to have a look at this. The frames should be timestamped sensibly (with the GPU STC).

I can't remember what the default buffer size is. If it is smaller than the frame size, then the first buffer would come through with the correct timestamp (and flags having MMAL_BUFFER_HEADER_FLAG_FRAME_START set), and subsequent buffers in the same frame would get MMAL_TIME_UNKNOWN until the last buffer in the frame would also have the MMAL_BUFFER_HEADER_FLAG_FRAME_END flag set. That would explain seeing some buffers with TIME_UNKNOWN, but not all of them.
I suspected that it is the value of MMAL_TIME_UNKNOWN - but I couldn't decipher the meaning of 1<<63 (my c understandings are somewhat limited...).
Unfortunately the second part of your answer is (at least at the moment) too high informatics for me, but I take from it that if all values of pts = MMAL_TIME_UNKNOWN something's still wrong. :)

I now tried to print out pts, dts, and the variable current_time, which is a variable in encoder_buffer_callback:
int64_t current_time = vcos_getmicrosecs64()/1000;
I don't know what current_time means, and if it can be a source of information for us. I will try to find that out.

As an output I get (pts, dts and current time in one file)

Code: Select all

pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130108930
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130108932
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110025
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110056
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110123
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110158
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110222
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110263
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110323
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110380
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110384
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110387
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110423
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110465
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110523
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110527
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110571
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110576
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110623
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110626
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110667
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110671
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110723
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110727
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110769
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110773
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110822
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110825
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110866
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110869
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110921
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110926
pts =-9223372036854775808
dts =-9223372036854775808
current time =1418130110936
My version of raspivid contains the following changes:
L904 - L907: added 3 int64_t variables
L921: line added to write value of current_time into timestamp3
L1095 - L1107: storing pts and dts in timestamp variables, and print everything out

Download-Link to the modified version of RaspiVid.c: https://dl.dropboxusercontent.com/u/25782105/RaspiVid.c

jamesh
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 24162
Joined: Sat Jul 30, 2011 7:41 pm

Re: dropped frames

Tue Dec 09, 2014 1:39 pm

Every frame has a time stamp attached to it to enable it to (simplistically) sync up properly with everything. That time stamp doesn't appear to be present. It should be attached by the GPU during the processing of the frame. If it is not attaching it then there is actually something wrong. So that needs to be looked in to - you appear have found a real bug, and one that has recently been introduced because this hasn't been seen before.
Principal Software Engineer at Raspberry Pi (Trading) Ltd.
Contrary to popular belief, humorous signatures are allowed. Here's an example...
“I think it’s wrong that only one company makes the game Monopoly.” – Steven Wright

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Tue Dec 09, 2014 1:48 pm

jamesh wrote:Every frame has a time stamp attached to it to enable it to (simplistically) sync up properly with everything. That time stamp doesn't appear to be present. It should be attached by the GPU during the processing of the frame. If it is not attaching it then there is actually something wrong. So that needs to be looked in to - you appear have found a real bug, and one that has recently been introduced because this hasn't been seen before.
Interesting - If I can help with anything (which I doubt), please let me know.

ethanol100
Posts: 587
Joined: Wed Oct 02, 2013 12:28 pm

Re: dropped frames

Tue Dec 09, 2014 2:34 pm

Has the time stamping ever worked for raspivid?

I want to add some infos and a version of raspivid to write the pts values.

As 6by9 has pointed out, only the first buffer of a frame split into several buffers has a valid time stamp. The only problem is, the buffer has its flag set to 0. No MMAL_BUFFER_HEADER_FLAG_FRAME_START is ever set, and I belief has never been set in previous version.

Additionally I have some problems with the RESET clock. I can get the time stamps with these modifications:

Code: Select all

diff --git a/host_applications/linux/apps/raspicam/RaspiVid.c b/host_applications/linux/apps/raspicam/RaspiVid.c
index afb8363..2ad1e03 100755
--- a/host_applications/linux/apps/raspicam/RaspiVid.c
+++ b/host_applications/linux/apps/raspicam/RaspiVid.c
@@ -134,6 +134,7 @@ typedef struct
    char  header_bytes[29];
    int  header_wptr;
    FILE *imv_file_handle;               /// File handle to write inline motion vectors to.
+   FILE *pts_file_handle;                    /// File timestamps
 } PORT_USERDATA;
 
 /** Structure containing all state information for the current run
@@ -183,10 +184,14 @@ struct RASPIVID_STATE_S
 
    int inlineMotionVectors;             /// Encoder outputs inline Motion Vectors
    char *imv_filename;                  /// filename of inline Motion Vectors output
-   
    int cameraNum;                       /// Camera number
    int settings;                        /// Request settings from the camera
    int sensor_mode;			/// Sensor mode. 0=auto. Check docs/forum for modes selected by other values.
+   int frame;
+   char *pts_file;
+   int save_pts;
+   int64_t starttime;
+   int64_t lasttime;
 };
 
 
@@ -240,6 +245,7 @@ static void display_valid_parameters(char *app_name);
 #define CommandCamSelect    24
 #define CommandSettings     25
 #define CommandSensorMode   26
+#define CommandSavePTS      27
 
 static COMMAND_LIST cmdline_commands[] =
 {
@@ -270,6 +276,7 @@ static COMMAND_LIST cmdline_commands[] =
    { CommandCamSelect,     "-camselect",  "cs", "Select camera <number>. Default 0", 1 },
    { CommandSettings,      "-settings",   "set","Retrieve camera settings and write to stdout", 0},
    { CommandSensorMode,    "-mode",       "md", "Force sensor mode. 0=auto. See docs for other modes available", 1},
+   { CommandSavePTS,       "-save-pts",   "pts","Save Timestamt to file", 1 },
 };
 
 static int cmdline_commands_size = sizeof(cmdline_commands) / sizeof(cmdline_commands[0]);
@@ -334,11 +341,11 @@ static void default_status(RASPIVID_STATE *state)
    state->splitWait = 0;
 
    state->inlineMotionVectors = 0;
-   
    state->cameraNum = 0;
    state->settings = 0;
    state->sensor_mode = 0;
-
+   state->frame = 0;
+   state->save_pts = 0;
    // Setup preview window defaults
    raspipreview_set_defaults(&state->preview_parameters);
 
@@ -696,6 +703,23 @@ static int parse_cmdline(int argc, const char **argv, RASPIVID_STATE *state)
          break;
       }
 
+      case CommandSavePTS:  // output filename
+      {
+         state->save_pts = 1;
+         int len = strlen(argv[i + 1]);
+         if (len)
+         {
+            state->pts_file = malloc(len + 1);
+            vcos_assert(state->pts_file);
+            if (state->pts_file)
+               strncpy(state->pts_file, argv[i + 1], len+1);
+            i++;
+         }
+         else
+            valid = 0;
+         break;
+      }
+
       default:
       {
          // Try parsing for any image specific parameters
@@ -888,6 +912,27 @@ static FILE *open_imv_filename(RASPIVID_STATE *pState)
    return new_handle;
 }
 
+static FILE *open_pts_filename(RASPIVID_STATE *pState)
+{
+   FILE *new_handle = NULL;
+   char *filename = NULL;
+
+   filename = pState->pts_file;
+
+   if (filename)
+      new_handle = fopen(filename, "wb");
+
+   if (pState->verbose)
+   {
+      if (new_handle)
+         fprintf(stderr, "Opening pts output file \"%s\"\n", filename);
+      else
+         fprintf(stderr, "Failed to open new pts file \"%s\"\n", filename);
+   }
+
+   return new_handle;
+}
+
 /**
  *  buffer header callback function for encoder
  *

@@ -1050,7 +1095,18 @@ static void encoder_buffer_callback(MMAL_PORT_T *port, MMAL_BUFFER_HEADER_T *buf
             }
             else
             {
-               bytes_written = fwrite(buffer->data, 1, buffer->length, pData->file_handle);            
+               bytes_written = fwrite(buffer->data, 1, buffer->length, pData->file_handle);
+               //printf("Bufferlag=%d\n",buffer->flags);
+               if(pData->pstate->save_pts && (buffer->flags & MMAL_BUFFER_HEADER_FLAG_FRAME_END || buffer->flags == 0 || buffer->flags & MMAL_BUFFER_HEADER_FLAG_KEYFRAME) && !(buffer->flags & MMAL_BUFFER_HEADER_FLAG_CONFIG))
+               {
+                  if(buffer->pts != MMAL_TIME_UNKNOWN && buffer->pts != pData->pstate->lasttime)
+                  {
+                    if(pData->pstate->frame==0)pData->pstate->starttime=buffer->pts;
+                    pData->pstate->lasttime=buffer->pts;
+                    fprintf(pData->pts_file_handle,"%d %f\n",pData->pstate->frame,(buffer->pts-pData->pstate->starttime)/1000000.);
+                    pData->pstate->frame++;
+                  }
+               }
             }
 
             mmal_buffer_header_mem_unlock(buffer);
@@ -1177,7 +1233,7 @@ static MMAL_STATUS_T create_camera_component(RASPIVID_STATE *state)
          .num_preview_video_frames = 3,
          .stills_capture_circular_buffer_height = 0,
          .fast_preview_resume = 0,
-         .use_stc_timestamp = MMAL_PARAM_TIMESTAMP_MODE_RESET_STC
+         .use_stc_timestamp = MMAL_PARAM_TIMESTAMP_MODE_RAW_STC
       };
       mmal_port_parameter_set(camera->control, &cam_config.hdr);
    }
@@ -1899,6 +1955,27 @@ int main(int argc, const char **argv)
             }
          }
 
+         state.callback_data.pts_file_handle = NULL;
+
+         if (state.pts_file)
+         {
+            if (state.pts_file[0] == '-')
+            {
+               state.callback_data.pts_file_handle = stdout;
+            }
+            else
+            {
+               state.callback_data.pts_file_handle = open_pts_filename(&state);
+            }
+
+            if (!state.callback_data.pts_file_handle)
+            {
+               // Notify user, carry on but discarding encoded output buffers
+               fprintf(stderr, "Error opening output file: %s\nNo output file will be generated\n",state.pts_file);
+               state.save_pts=0;
+            }
+         }
+
          if(state.bCircularBuffer)
          {
             if(state.bitrate == 0)
@@ -2110,6 +2187,8 @@ error:
          fclose(state.callback_data.file_handle);
       if (state.callback_data.imv_file_handle && state.callback_data.imv_file_handle != stdout)
          fclose(state.callback_data.imv_file_handle);
+      if (state.callback_data.pts_file_handle && state.callback_data.pts_file_handle != stdout)
+         fclose(state.callback_data.pts_file_handle);
 
       /* Disable components */
       if (state.encoder_component)
The binary can be downloaded for testing at http://www2.geo.uni-bonn.de/members/kroener/raspivid

Can be used with:

Code: Select all

./raspivid -v -o test.h264 -pts pts.dat -t 120000
The file "pts.dat" then contains frame number and time of each frame.

When I record a two minute video I get a lost frame after about 500 pictures, but overall it has a constant frame rate.
Last edited by ethanol100 on Tue Dec 09, 2014 3:22 pm, edited 1 time in total.

6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Tue Dec 09, 2014 2:49 pm

Thanks ethanol100.
I did have it in the back of my mind that it might have been the timestamping mode at fault, but I have no access to anything here for testing. I will have a look again at RESET_STC as it should work, but obviously doesn't.
MMAL_BUFFER_HEADER_FLAG_FRAME_START should be supported, but no guarantees. It depends on what the components themselves emit as flags, and FRAME_START isn't that useful generally. It may actually be a camera bug in not sending FRAME_START for the codec to forward on, but that is speculation as I have no code here.

I'll try to have a play tonight. At least we have a useful marker in the sand with the RAW_STC mode (the V4L2 driver uses that anyway IIRC, as did the Android adaptation for the other Videocore related chips).
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

ethanol100
Posts: 587
Joined: Wed Oct 02, 2013 12:28 pm

Re: dropped frames

Tue Dec 09, 2014 3:10 pm

RESET_STC is working, somehow. I think I'm just too dumb to use it. The first buffer containing MMAL_BUFFER_HEADER_FLAG_CONFIG has a time value of 0, but the first frame has a value different form 0. If I then manually substract the time of the first frame, after about 5 seconds the time stamp counter wraps and I get negative values. Would the start of the camera/component or the first frame be used to reset the clock?

I guess it is not the RESET_STC which creates the problem.

If I manually get the buffer from the camera video port, each frame is in one buffer and has only the flag "FRAME_END" set.

6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Tue Dec 09, 2014 4:21 pm

ethanol100 wrote:RESET_STC is working, somehow. I think I'm just too dumb to use it. The first buffer containing MMAL_BUFFER_HEADER_FLAG_CONFIG has a time value of 0, but the first frame has a value different form 0. If I then manually substract the time of the first frame, after about 5 seconds the time stamp counter wraps and I get negative values. Would the start of the camera/component or the first frame be used to reset the clock?

I guess it is not the RESET_STC which creates the problem.
It was supposed to be that every time you started capturing data on output[1] that the timestamps would reset to 0. That could be either through enabling the port with the MMAL_PARAMETER_CAPTURING already set, or enabling MMAL_PARAMETER_CAPTURING on the enabled port.
That makes recording single clips easy, but makes implementing things like pause much harder.
I'll have a look later to see if there is an obvious reason RESET_STC is doing daft things. I vaguely remember a bug with it before but thought it had been fixed. I guess not.
ethanol100 wrote:If I manually get the buffer from the camera video port, each frame is in one buffer and has only the flag "FRAME_END" set.
Ta, that was my suspicion.
Actually just checking the IL headers there is no FRAME_START buffer flag there, so the camera component can't create it (MMAL is actually sitting on top of part of IL)
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Tue Dec 09, 2014 4:42 pm

Thank you for this, ethanol100!!

I analyzed pts.dat, and I found that I do have a problem....Picture here: https://www.dropbox.com/s/ux6zmxdpe9o5k ... s.jpg?dl=0

6by9 wrote: - run your new raspivid (it will have been installed to the normal /opt/vc directory by buildme) and see what the timestamps are.
If there are jumps of 80ms between some buffers then your SD card isn't keeping up. Retest with streaming to /dev/nul to confirm that the timestamps are then even.
I wanted to try this with your raspivid version, ethanol100, but unfortunately it doesn't seem to work when I write the video file to /dev/null . A pts.dat file is generated, but it's empty...

ethanol100
Posts: 587
Joined: Wed Oct 02, 2013 12:28 pm

Re: dropped frames

Tue Dec 09, 2014 4:54 pm

Running"./raspivid -o /dev/null -pts null.pts -t 150000" gives me a list of timestamps without and dropped frames.
Using /run/shm, I need to reduce the recoding time, i.e. "./raspivid -o /run/shm/shm.h264 -pts shm.pts -t 60000" creates a video without dropped frames.

How does reducing bitrate influence the results, i.e "-b 5000000"?

6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Wed Dec 10, 2014 9:45 am

Problem found and hopefully fixed with RESET_STC timestamping mode. I'll try to get it pushed in the next couple of days - it'll be a firmware update. That mode ha never been used in anger, hence the bug lurking there undetected.

Minor enhancement to the PTS logging - save the delta as well, and format it nicely. You were also dropping the timestamp of the very first frame in RESET_STC mode (which I know you can't use yet!) as lasttime = 0 = buffer->pts.

Code: Select all

@@ -1050,7 +1096,24 @@ static void encoder_buffer_callback(MMAL_PORT_T *port, MMAL_BUFFER_HEADER_T *buf
             }
             else
             {
-               bytes_written = fwrite(buffer->data, 1, buffer->length, pData->file_handle);
+               bytes_written = fwrite(buffer->data, 1, buffer->length, pData->file_handle);
+               if(pData->pstate->save_pts &&
+                  (buffer->flags & MMAL_BUFFER_HEADER_FLAG_FRAME_END ||
+                   buffer->flags == 0 ||
+                   buffer->flags & MMAL_BUFFER_HEADER_FLAG_KEYFRAME) &&
+                 !(buffer->flags & MMAL_BUFFER_HEADER_FLAG_CONFIG))
+               {
+                  if(buffer->pts != MMAL_TIME_UNKNOWN &&
+                     (!buffer->pts || buffer->pts != pData->pstate->lasttime))
+                  {
+                    if(pData->pstate->frame==0)
+                      pData->pstate->starttime=buffer->pts;
+                    fprintf(pData->pts_file_handle,"%3d %3.6f delta %llu\n",pData->pstate->frame,(buffer->pts)/1000000.,
+                               buffer->pts - pData->pstate->lasttime);
+                    pData->pstate->lasttime=buffer->pts;
+                    pData->pstate->frame++;
+                  }
+               }
             }
I'll double check those diffs later and do a PR to update raspivid, as logging timestamps could be quite useful in future.
ethanol100 - I hope you don't mind me being the commit author instead of you. Or you could merge my diffs with yours and do a PR. I'll get asked to review it anyway so could catch any needed corrections then.
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Wed Dec 10, 2014 9:48 am

I should also say that I'm seeing no frame drops at all when running to /dev/null, and running at 25fps is giving nice uniform deltas of 39.8ms too.
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

ethanol100
Posts: 587
Joined: Wed Oct 02, 2013 12:28 pm

Re: dropped frames

Wed Dec 10, 2014 10:22 am

Thanks for looking at this issue.

You are right, the case of lasttime = 0 = buffer->pts would be a problem, but I had to introduce the lasttime after changing to RAW_STC(some buffer had valid timestamps not only in the first buffer, I-frames?Had not enough time to investigate..) and had not thought about it. And nicer formating and delta times seems to be a good idea.

No problem, you can just commit it.

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Mon Dec 15, 2014 1:14 pm

Hello everybody,

As my problem still persists, I invested quite some hours trying to get to the ground of the frame loss problem, with the help of ethanol100's modified version of raspivid, which outputs the frame timestamps.

I wrote a small script which records videos to 3 different locations, /run/shm/, /dev/null and /home/pi. 2 videos were recorded to each location. I then analyzed the frame timestamps of the 6 videos. In total I ran the script 12 times, with different settings in order to find out what causes the frame losses. I got some results, but they are not very clear.

The data suggests amongst other things that writing to the SD card isn't the reason for frame losses.

On this drop-box folder https://www.dropbox.com/sh/w9c39htdnckd ... NsU7a?dl=0 you'll find:
- the data + analysis in a spreadsheet document (.xslx version and .ods version available, other formats just ask)
- the script used for recording the 6 videos for one data collection
- links to the videos recorded, can be found in the spreadsheet document

link to post from ethanol100 with explanation and link to his modified version of raspivid: http://www.raspberrypi.org/forums/viewt ... 24#p652124

It would be great if some of you could have a look at my investigation, and could give their opinion about it. I'm also interested in suggestions for different test configurations.

--> Could the camera be faulty? I didn't treat it especially well.

6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Mon Dec 15, 2014 2:05 pm

el_cid wrote:--> Could the camera be faulty? I didn't treat it especially well.
I'm at work so can't spend time analysing your logs, but as I was reading your latest description I was wondering about data corruption.

The CSI-2 receiver peripheral does check the checksum of the incoming frames, and IIRC it will ditch frames where the CRC fails. That would lead to frame drops as you are reporting.

It's likely to be quite verbose, but you could try (from memory)

Code: Select all

sudo vcgencmd set_logging level=192
to increase the amount of logging returned via sudo vcdbg log msg. (I could be totally wrong with this command line as there are two types of logging and I can't remember which is used in the Pi codebase. I can check tonight)

Grep the results for "drop" (you'll need the 2>&1 trick as vcdbg writes to stderr instead of stdout) and you may find logging indicating that it is dropping frames due to CRC errors.
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Mon Dec 15, 2014 2:37 pm

Thank you for your answer, 6by9.

So while recording a video I need enter in the terminal

Code: Select all

sudo vcdbg log msg 2>&1 | grep -i drop
Is that correct?

Just for better understanding: vcdbg log msg shows the logs since how much time? since start up of the pi?

6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Mon Dec 15, 2014 2:44 pm

el_cid wrote:So while recording a video I need enter in the terminal

Code: Select all

sudo vcdbg log msg 2>&1 | grep -i drop
Is that correct?
Yes
el_cid wrote:Just for better understanding: vcdbg log msg shows the logs since how much time? since start up of the pi?
It logs into a circular buffer, so it depends on how many logging messages are written by the GPU as to what the time period is that it covers. Default logging level is very low, but the vcgencmd line will turn it on for all the multimedia middleware so it will fill up and wrap around fairly fast.
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

ethanol100
Posts: 587
Joined: Wed Oct 02, 2013 12:28 pm

Re: dropped frames

Mon Dec 15, 2014 3:06 pm

el_cid wrote:--> Could the camera be faulty? I didn't treat it especially well.
How does the flat ribbon cable looks like? Are there any kinks or broken lines?
Could you try to remove the cable and reattach it, on both ends?

I have tried your commands and I never get a dropped frame. It really seems to be a problem with your camera, or its connection.

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Mon Dec 15, 2014 3:07 pm

I ran my usual script, and while running it, I frequently entered the above command, but grep never found an entry with "drop". Nevertheless looking at the pts-data I find the following frame losses:

Code: Select all

writing to         data sample           frame loss in %
/run/shm             1                      28.34
/run/shm             2                     32.63
/dev/null            1                       30.76
/dev/null            2                       23.03
/home/pi             1                      30.28
/home/pi             2                      0.252 *
*this large difference could be because in the last video I didn't do anymore movements.

el_cid
Posts: 27
Joined: Thu Jun 05, 2014 2:29 pm
Location: Switzerland

Re: dropped frames

Mon Dec 15, 2014 3:11 pm

ethanol100 wrote:
el_cid wrote:--> Could the camera be faulty? I didn't treat it especially well.
How does the flat ribbon cable looks like? Are there any kinks or broken lines?
Could you try to remove the cable and reattach it, on both ends?

I have tried your commands and I never get a dropped frame. It really seems to be a problem with your camera, or its connection.
there are kinks, but no broken lines.

Great that you have no dropped frames! That would mean that the problem could be solved easily. I would prefer that just as much. :)

RecDev
Posts: 5
Joined: Wed Jan 28, 2015 11:56 am

Re: dropped frames

Wed Jan 28, 2015 12:57 pm

Sadly I am also facing this issue.
I record both video and audio at the same time to a connected USB storage.

Now I'm already disappointed that the framerate is off by so much - I try to record with 20 fps and get 20.3(!) - but that's a problem that could be solved somehow if at least the amount of frames was constant.

I created a lot of 2 hour long test recordings, and they currently are simply unreliable. It varies between no noticeable loss and around 10 seconds, and the loss is obviously not uniformly distributed (evident from the displayed timer that the camera is filming). Syncing audio to this is video output is basically impossible, as it needs to happen automatically. The amount of changes I'd probably need to make to raspivid and probaly alsa arecord are currently beyond my scope, and I do wonder why it's so unreliable.

I don't remember having this problem when the USB drive was formatted as XFS, but that is simply not an option either as I need it to be read without a hassle in Windows - which, between Windows and Linux, only allows Ext4 (don't even get me started on Fat32 in this context)

Does anyone have any suggestions on how to deal with this?
I'm using the Camera Board on a B+.

6by9
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 7568
Joined: Wed Dec 04, 2013 11:27 am
Location: ZZ9 Plural Z Alpha, aka just outside Cambridge.

Re: dropped frames

Wed Jan 28, 2015 1:58 pm

RecDev wrote:Sadly I am also facing this issue.
I record both video and audio at the same time to a connected USB storage.

Now I'm already disappointed that the framerate is off by so much - I try to record with 20 fps and get 20.3(!) - but that's a problem that could be solved somehow if at least the amount of frames was constant.
The sensor is being driven from a 25MHz crystal when it should be a 24.8MHz one, hence it is a couple of percent fast.

What EXACTLY is the command line you are running?
Are you requesting a low bitrate? The rate control algo can then sometimes decide to not encode frames as it is over bit budget.
Have you tried redirecting the video data to /dev/null whilst recording the PTS values (see earlier in this thread) to see what the timestamps come out as?
Software Engineer at Raspberry Pi Trading. Views expressed are still personal views.
I'm not interested in doing contracts for bespoke functionality - please don't ask.

Return to “Camera board”