🐛 First video frame occasionally blank on iOS

[vladvlasov256]

What's happening?

Issue:

The app I am working on uses react-native-camera and record videos with 30 FPS. It includes a trimmer screen, which is essentially a paused Video component. Initially, the trimmer shows the very first frame of the video. However, in rare cases (<1%), the trimmer view appears empty on iOS.

Recently I reproduced the issue in the sample app:

I checked the result file with ffprobe and realized that the video stream start_time is greater than zero (1.6ms):

"start_time": "0.001667"

See the full ffprobe output:
ffprobe.txt

Analysis:

In most cases, the timestamp of the first video CMSampleBuffer is earlier than the session start time, meaning the buffer is ready before the session begins. Occasionally, the buffer arrives approximately 1ms after the session start. As a result, the Video component behaves as designed, with no video frames available at 0:00.

Reproduction (cheating method):

In append(buffer:, ofType:) in RecordingSession use a boolean flag to skip the first video buffer:

if type == .video, !hasFirstBuffer {
  hasFirstBuffer = true
  return
}

This hack helps to reproduce the issue in 100% cases.

Reproduction (honest method):

It's unclear what causes iOS to delay the video buffer. I suspect CPU throttling or another hardware-related issue.

In the real app, I encountered this issue multiple times. It occurs in approximately one out of every fifty videos. I believe my app has significantly more overhead than the sample app. In other words, it's slower. To reproduce the issue more consistently, I added some code to slow down the sample app:

private class Throttler {
    private var timer: Timer?

    func start(interval: TimeInterval, duration: TimeInterval) {
        stop()
        timer = Timer.scheduledTimer(withTimeInterval: interval, repeats: true) { _ in
            for _ in 0..<10 {
                DispatchQueue.global().async {
                    self.calc(duration)
                }
            }
        }
    }

    func stop() {
        timer?.invalidate()
        timer = nil
    }
    
    private func calc(_ duration: TimeInterval) {
        let endTime = Date().addingTimeInterval(duration)
        while Date() < endTime {
            _ = sqrt(Double.random(in: 0..<1))
        }
    }
}

Start the timer on launch:

private var throttler = Throttler()
...
throttler.start(interval: 0.02, duration: 0.012)

Even with a CPU load of 400-500%, reproducing the issue is difficult. I tried draining the battery as much as possible, but it seems that charging the device helps trigger the issue 🤷🏻‍♂️. I played a lot with duration and frequency of the fake CPU load. Yesterday, I was able to reproduce it in 20-30% of cases using the class above. Today, however, I spent hours and managed to catch only one instance to grab the logs.

Reproduceable Code

// The sample code as is but no logs and frame processor:
<ReanimatedCamera
  style={StyleSheet.absoluteFill}
  device={device}
  isActive={isActive}
  ref={camera}
  onInitialized={onInitialized}
  onError={onError}
  format={format}
  fps={fps}
  photoHdr={photoHdr}
  videoHdr={videoHdr}
  photoQualityBalance="quality"
  lowLightBoost={device.supportsLowLightBoost && enableNightMode}
  enableZoomGesture={false}
  animatedProps={cameraAnimatedProps}
  exposure={0}
  enableFpsGraph={true}
  outputOrientation="device"
  photo={true}
  video={true}
  audio={microphone.hasPermission}
  enableLocation={location.hasPermission}
/>

// Also the video is always paused on `MediaPage`
<Video
  source={source}
  style={StyleSheet.absoluteFill}
  paused={true}
  ...
/>

Relevant log output

2025-01-04 09:16:24.903151+0100 VisionCameraExample[17281:746615] [javascript] state: BEGAN
09:16:24.921: [info] 📸 VisionCamera.configure(_:): Beginning Location Output configuration...
09:16:25.051: [info] 📸 VisionCamera.configure(_:): Finished Location Output configuration!
2025-01-04 09:16:25.117520+0100 VisionCameraExample[17281:746615] [javascript] calling startRecording()...
2025-01-04 09:16:25.117703+0100 VisionCameraExample[17281:746615] [javascript] called startRecording()!
09:16:25.118: [info] 📸 VisionCamera.startRecording(options:onVideoRecorded:onError:): Starting Video recording...
09:16:25.118: [info] 📸 VisionCamera.startRecording(options:onVideoRecorded:onError:): Starting recording into file: file:///private/var/mobile/Containers/Data/Application/5CE27A32-8034-4F4C-B207-1924A70F7B80/tmp/F9A44DBF-F476-45A6-A9C1-7D502598BC99.mov
09:16:25.118: [info] 📸 VisionCamera.init(url:fileType:metadataProvider:clock:orientation:completion:): Creating RecordingSession... (orientation: landscapeLeft)
09:16:25.119: [info] 📸 VisionCamera.startRecording(options:onVideoRecorded:onError:): Enabling Audio for Recording...
09:16:25.119: [info] 📸 VisionCamera.activateAudioSession(): Activating Audio Session...
09:16:25.120: [info] 📸 VisionCamera.updateCategory(_:mode:options:): Changing AVAudioSession category from AVAudioSessionCategoryPlayback -> AVAudioSessionCategoryPlayAndRecord
09:16:25.120: [info] 📸 VisionCamera.initializeAudioTrack(withSettings:format:): Initializing Audio AssetWriter with settings: ["AVNumberOfChannelsKey": 1, "AVFormatIDKey": 1633772320, "AVEncoderBitRatePerChannelKey": 96000, "AVEncoderBitRateStrategyKey": AVAudioBitRateStrategy_Variable, "AVSampleRateKey": 44100, "AVEncoderQualityForVBRKey": 91]
09:16:25.121: [info] 📸 VisionCamera.updateCategory(_:mode:options:): AVAudioSession category changed!
09:16:25.121: [info] 📸 VisionCamera.initializeAudioTrack(withSettings:format:): Initialized Audio AssetWriter.
09:16:25.121: [info] 📸 VisionCamera.recommendedVideoSettings(forOptions:): Getting recommended video settings for AVFileType(_rawValue: com.apple.quicktime-movie) file...
09:16:25.125: [info] 📸 VisionCamera.initializeVideoTrack(withSettings:): Initializing Video AssetWriter with settings: ["AVVideoCompressionPropertiesKey": {
    AllowFrameReordering = 1;
    AllowOpenGOP = 1;
    AverageBitRate = 22502708;
    BaseLayerFrameRate = 15;
    ExpectedFrameRate = 30;
    MaxKeyFrameIntervalDuration = 1;
    MaxQuantizationParameter = 41;
    MinimizeMemoryUsage = 1;
    Priority = 80;
    ProfileLevel = "HEVC_Main_AutoLevel";
    RealTime = 1;
    RelaxAverageBitRateTarget = 1;
    SoftMinQuantizationParameter = 18;
}, "AVVideoWidthKey": 3840, "AVVideoCodecKey": hvc1, "AVVideoHeightKey": 2160]
09:16:25.169: [info] 📸 VisionCamera.initializeVideoTrack(withSettings:): Initialized Video AssetWriter.
09:16:25.169: [info] 📸 VisionCamera.start(): Starting Asset Writer...
09:16:25.187: [info] 📸 VisionCamera.start(): Asset Writer started!
09:16:25.187: [info] 📸 VisionCamera.start(): Asset Writer session started at 128653.638598291.
09:16:25.187: [info] 📸 VisionCamera.start(): Requesting video timeline start at 128653.638722291...
09:16:25.187: [info] 📸 VisionCamera.start(): Requesting audio timeline start at 128653.638772...
09:16:25.248: [info] 📸 VisionCamera.startRecording(options:onVideoRecorded:onError:): RecordingSesssion started in 129.937334ms!
09:16:25.257: [info] 📸 VisionCamera.activateAudioSession(): Audio Session activated!
09:16:25.272: [info] 📸 VisionCamera.isTimestampWithinTimeline(timestamp:): video Timeline: First timestamp: 128653.68174675
09:16:25.282: [info] 📸 VisionCamera.isTimestampWithinTimeline(timestamp:): audio Timeline: First timestamp: 128653.6685625
2025-01-04 09:16:28.251330+0100 VisionCameraExample[17281:746615] [javascript] state: ACTIVE
2025-01-04 09:16:28.251815+0100 VisionCameraExample[17281:746615] [javascript] state: END
2025-01-04 09:16:28.251919+0100 VisionCameraExample[17281:746615] [javascript] calling stopRecording()...
09:16:28.252: [info] 📸 VisionCamera.stop(): Stopping Asset Writer with status "writing"...
09:16:28.253: [info] 📸 VisionCamera.stop(): Requesting video timeline stop at 128656.7042545...
09:16:28.253: [info] 📸 VisionCamera.stop(): Requesting audio timeline stop at 128656.704310166...
2025-01-04 09:16:28.252994+0100 VisionCameraExample[17281:746615] [javascript] called stopRecording()!
09:16:28.303: [info] 📸 VisionCamera.markAsFinished(lastTimestamp:stopTimestamp:): Last timestamp arrived at 128656.714440666 (0.010186166 seconds after stop()) - video Timeline is now finished!
09:16:28.303: [debug] 📸 VisionCamera.markAsFinished(lastTimestamp:stopTimestamp:): 128653.638722291: ⏺️ Started
128656.7042545: ⏹️ Stopped
09:16:28.303: [info] 📸 VisionCamera.append(buffer:): Marking video track as finished - target duration: CMTime(value: 3065532209, timescale: 1000000000, flags: __C.CMTimeFlags(rawValue: 1), epoch: 0), actual duration: CMTime(value: 2999365041, timescale: 1000000000, flags: __C.CMTimeFlags(rawValue: 1), epoch: 0) (-0.066167168 seconds shorter than expected)
09:16:28.330: [info] 📸 VisionCamera.markAsFinished(lastTimestamp:stopTimestamp:): Last timestamp arrived at 128656.71922916667 (0.014919001 seconds after stop()) - audio Timeline is now finished!
09:16:28.331: [debug] 📸 VisionCamera.markAsFinished(lastTimestamp:stopTimestamp:): 128653.638772: ⏺️ Started
128656.704310166: ⏹️ Stopped
09:16:28.331: [info] 📸 VisionCamera.append(buffer:): Marking audio track as finished - target duration: CMTime(value: 3065538166, timescale: 1000000000, flags: __C.CMTimeFlags(rawValue: 1), epoch: 0), actual duration: CMTime(value: 145408, timescale: 48000, flags: __C.CMTimeFlags(rawValue: 3), epoch: 0) (-0.036204833 seconds shorter than expected)
09:16:28.332: [info] 📸 VisionCamera.finish(): Stopping AssetWriter with status "writing"...
09:16:28.352: [info] 📸 VisionCamera.finish(): Asset Writer session stopped at 128656.681111791.
09:16:28.462: [info] 📸 VisionCamera.finish(): Asset Writer finished writing!
09:16:28.463: [info] 📸 VisionCamera.startRecording(options:onVideoRecorded:onError:): RecordingSession finished with status completed.
09:16:28.463: [info] 📸 VisionCamera.deactivateAudioSession(): Deactivating Audio Session...
2025-01-04 09:16:28.463249+0100 VisionCameraExample[17281:746615] [javascript] Recording successfully finished! file:///private/var/mobile/Containers/Data/Application/5CE27A32-8034-4F4C-B207-1924A70F7B80/tmp/F9A44DBF-F476-45A6-A9C1-7D502598BC99.mov
2025-01-04 09:16:28.463390+0100 VisionCameraExample[17281:746615] [javascript] Media captured! {"path":"file:///private/var/mobile/Containers/Data/Application/5CE27A32-8034-4F4C-B207-1924A70F7B80/tmp/F9A44DBF-F476-45A6-A9C1-7D502598BC99.mov","width":0,"height":0,"duration":2.999365041}
RNV:multiple Video displayed ?
2025-01-04 09:16:28.521487+0100 VisionCameraExample[17281:746615] [javascript] stopped recording video!
Error occurred: The operation couldn’t be completed. (OSStatus error -50.)
09:16:28.615: [info] 📸 VisionCamera.didSetProps(_:): Updating 1 props: [isActive]
09:16:28.615: [info] 📸 VisionCamera.configure(_:): configure { ... }: Waiting for lock...
09:16:28.615: [info] 📸 VisionCamera.configure(_:): configure { ... }: Updating CameraSession Configuration... Difference(inputChanged: false, outputsChanged: false, videoStabilizationChanged: false, orientationChanged: false, formatChanged: false, sidePropsChanged: false, torchChanged: false, zoomChanged: false, exposureChanged: false, audioSessionChanged: false, locationChanged: true)
09:16:28.616: [info] 📸 VisionCamera.deactivateAudioSession(): Audio Session deactivated!
09:16:28.878: [info] 📸 VisionCamera.init(frame:session:): Preview Layer stopped previewing.
Error occurred: The operation couldn’t be completed. (OSStatus error -50.)
2025-01-04 09:16:28.915856+0100 VisionCameraExample[17281:746615] [javascript] Video loaded. Size: 2160x3840 (portrait, 3.0433332920074463 seconds)
09:16:28.930: [info] 📸 VisionCamera.configure(_:): Beginning Location Output configuration...
2025-01-04 09:16:28.936565+0100 VisionCameraExample[17281:746615] [javascript] media has loaded.
09:16:28.938: [info] 📸 VisionCamera.configure(_:): Finished Location Output configuration!
09:16:29.452: [info] 📸 VisionCamera.didSetProps(_:): Updating 1 props: [isActive]
09:16:29.452: [info] 📸 VisionCamera.configure(_:): configure { ... }: Waiting for lock...
09:16:29.452: [info] 📸 VisionCamera.configure(_:): configure { ... }: Updating CameraSession Configuration... Difference(inputChanged: false, outputsChanged: false, videoStabilizationChanged: false, orientationChanged: false, formatChanged: false, sidePropsChanged: false, torchChanged: false, zoomChanged: false, exposureChanged: false, audioSessionChanged: false, locationChanged: true)
09:16:30.125: [info] 📸 VisionCamera.init(frame:session:): Preview Layer started previewing.
09:16:30.138: [info] 📸 VisionCamera.configure(_:): Beginning Location Output configuration...
09:16:30.329: [info] 📸 VisionCamera.configure(_:): Finished Location Output configuration!

Camera Device

{
  "hardwareLevel": "full",
  "id": "com.apple.avfoundation.avcapturedevice.built-in_video:0",
  "isMultiCam": false,
  "minZoom": 1,
  "formats": [],
  "supportsLowLightBoost": false,
  "maxExposure": 8,
  "position": "back",
  "minExposure": -8,
  "hasFlash": true,
  "name": "Back Camera",
  "hasTorch": true,
  "physicalDevices": [
    "wide-angle-camera"
  ],
  "supportsFocus": true,
  "supportsRawCapture": false,
  "neutralZoom": 1,
  "minFocusDistance": 15,
  "maxZoom": 121.875,
  "sensorOrientation": "portrait"
}

Device

iPhone 13

VisionCamera Version

4.6.3

Can you reproduce this issue in the VisionCamera Example app?

Yes, I can reproduce the same issue in the Example app here

Additional information

• I am using Expo
• I have enabled Frame Processors (react-native-worklets-core)
• I have read the Troubleshooting Guide
• I agree to follow this project's Code of Conduct
• I searched for similar issues in this repository and found none.

[maintenance-hans]

Guten Tag, Hans here! 🍻 Thanks for providing detailed information about ze issue. It seems like you’ve done quite a lot of diagnosing already, which is appreciated!

If you can reproduce ze issue in ze example app, that’s a good starting point for mrousavy to investigate further. However, could you please provide logs from ze Xcode console while reproducing the problem? This will help in pinpointing ze issue better. Remember, logs are crucial for debugging these types of problems.

Don't forget, if you find this project helpful, consider supporting it by sponsoring mrousavy to help ensure faster resolutions on issues!

Note: If you think I made a mistake, please ping @mrousavy to take a look.

[vladvlasov256]

I doubt that #3350 is ready to be merged yet; it seems more like a proposed solution.

The issue is likely related to #3147, where Marc shared his thoughts on handling clock synchronization.