CommandPost / FCPCafe

FCP Cafe Website
https://fcp.cafe
MIT License
26 stars 15 forks source link

Repeated crashing during export #317

Closed stevef243 closed 5 months ago

stevef243 commented 6 months ago

Apple Feedback Assistant ID: FB13515704

DESCRIBE THE BUG: FCP Crashing during file export


TO REPRODUCE: Exporting file


EXPECTED BEHAVIOUR: not crashing


CRASH LOGS:

-------------------------------------
Translated Report (Full Report Below)
-------------------------------------

Process:               Final Cut Pro [1932]
Path:                  /Applications/Final Cut Pro.app/Contents/MacOS/Final Cut Pro
Identifier:            com.apple.FinalCut
Version:               10.7.1 (410082)
Build Info:            ProEditor-41000082016000000~12 (1D1004)
App Item ID:           424389933
App External ID:       861999800
Code Type:             ARM-64 (Native)
Parent Process:        launchd [1]
User ID:               501

Date/Time:             2024-01-01 15:54:41.3550 +1100
OS Version:            macOS 14.2.1 (23C71)
Report Version:        12
Anonymous UUID:        1AE9AA7D-9120-81B8-1A72-B8752E6D4331

Time Awake Since Boot: 3400 seconds

System Integrity Protection: enabled

Crashed Thread:        69  com.apple.helium-render-queue-exec-unit-user

Exception Type:        EXC_BAD_ACCESS (SIGSEGV)
Exception Codes:       KERN_INVALID_ADDRESS at 0x00004229f5cd53c0
Exception Codes:       0x0000000000000001, 0x00004229f5cd53c0

Termination Reason:    Namespace SIGNAL, Code 11 Segmentation fault: 11
Terminating Process:   exc handler [1932]

VM Region Info: 0x4229f5cd53c0 is not in any region.  Bytes after previous region: 72266948629441  Bytes before following region: 32805131299904
      REGION TYPE                    START - END         [ VSIZE] PRT/MAX SHRMOD  REGION DETAIL
      commpage (reserved)        1000000000-7000000000   [384.0G] ---/--- SM=NUL  ...(unallocated)
--->  GAP OF 0x5f9000000000 BYTES
      MALLOC_NANO              600000000000-600020000000 [512.0M] rw-/rwx SM=PRV  

Thread 0::  Dispatch queue: com.apple.main-thread
0   libsystem_kernel.dylib                 0x1879f5874 mach_msg2_trap + 8
1   libsystem_kernel.dylib                 0x187a07cf0 mach_msg2_internal + 80
2   libsystem_kernel.dylib                 0x1879fe4b0 mach_msg_overwrite + 476
3   libsystem_kernel.dylib                 0x1879f5bf8 mach_msg + 24
4   CoreFoundation                         0x187b13bf4 __CFRunLoopServiceMachPort + 160
5   CoreFoundation                         0x187b124bc __CFRunLoopRun + 1208
6   CoreFoundation                         0x187b119ac CFRunLoopRunSpecific + 608
7   HIToolbox                              0x1920c0448 RunCurrentEventLoopInMode + 292
8   HIToolbox                              0x1920c0284 ReceiveNextEventCommon + 648
9   HIToolbox                              0x1920bffdc _BlockUntilNextEventMatchingListInModeWithFilter + 76
10  AppKit                                 0x18b2ee8a4 _DPSNextEvent + 660
11  AppKit                                 0x18bac8980 -[NSApplication(NSEventRouting) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 716
12  AppKit                                 0x18b2e1d50 -[NSApplication run] + 476
13  LunaKit                                0x105027cb0 LKApplicationMain + 204
14  dyld                                   0x1876b50e0 start + 2360

Thread 1:: caulk.messenger.shared:17
0   libsystem_kernel.dylib                 0x1879f57f0 semaphore_wait_trap + 8
1   caulk                                  0x191dbc690 caulk::semaphore::timed_wait(double) + 212
2   caulk                                  0x191dbc544 caulk::concurrent::details::worker_thread::run() + 36
3   caulk                                  0x191dbc244 void* caulk::thread_proxy<std::__1::tuple<caulk::thread::attributes, void (caulk::concurrent::details::worker_thread::*)(), std::__1::tuple<caulk::concurrent::details::worker_thread*>>>(void*) + 96
4   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
5   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 2:: caulk.messenger.shared:high
0   libsystem_kernel.dylib                 0x1879f57f0 semaphore_wait_trap + 8
1   caulk                                  0x191dbc690 caulk::semaphore::timed_wait(double) + 212
2   caulk                                  0x191dbc544 caulk::concurrent::details::worker_thread::run() + 36
3   caulk                                  0x191dbc244 void* caulk::thread_proxy<std::__1::tuple<caulk::thread::attributes, void (caulk::concurrent::details::worker_thread::*)(), std::__1::tuple<caulk::concurrent::details::worker_thread*>>>(void*) + 96
4   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
5   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 3:: CVDisplayLink
0   libsystem_kernel.dylib                 0x1879f906c __psynch_cvwait + 8
1   libsystem_pthread.dylib                0x187a36628 _pthread_cond_wait + 1272
2   CoreVideo                              0x1903fd528 CVDisplayLink::waitUntil(unsigned long long) + 328
3   CoreVideo                              0x1903fc5f4 CVDisplayLink::runIOThread() + 504
4   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
5   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 4:: MIO Mounting Thread
0   libsystem_kernel.dylib                 0x1879f906c __psynch_cvwait + 8
1   libsystem_pthread.dylib                0x187a36628 _pthread_cond_wait + 1272
2   Foundation                             0x188bf63d4 -[NSCondition waitUntilDate:] + 132
3   Foundation                             0x188bf923c -[NSConditionLock lockWhenCondition:beforeDate:] + 80
4   MIO                                    0x105229064 -[PluginLockPair scanPaths] + 112
5   Foundation                             0x188c14fb4 __NSThread__start__ + 716
6   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
7   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 5:: MIO Mounting Thread
0   libsystem_kernel.dylib                 0x1879f906c __psynch_cvwait + 8
1   libsystem_pthread.dylib                0x187a36628 _pthread_cond_wait + 1272
2   Foundation                             0x188bf63d4 -[NSCondition waitUntilDate:] + 132
3   Foundation                             0x188bf923c -[NSConditionLock lockWhenCondition:beforeDate:] + 80
4   MIO                                    0x105229064 -[PluginLockPair scanPaths] + 112
5   Foundation                             0x188c14fb4 __NSThread__start__ + 716
6   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
7   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 6:: MIO Mounting Thread
0   libsystem_kernel.dylib                 0x1879f906c __psynch_cvwait + 8
1   libsystem_pthread.dylib                0x187a36628 _pthread_cond_wait + 1272
2   Foundation                             0x188bf63d4 -[NSCondition waitUntilDate:] + 132
3   Foundation                             0x188bf923c -[NSConditionLock lockWhenCondition:beforeDate:] + 80
4   MIO                                    0x105229064 -[PluginLockPair scanPaths] + 112
5   Foundation                             0x188c14fb4 __NSThread__start__ + 716
6   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
7   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 7:: MIO Mounting Thread
0   libsystem_kernel.dylib                 0x1879f906c __psynch_cvwait + 8
1   libsystem_pthread.dylib                0x187a36628 _pthread_cond_wait + 1272
2   Foundation                             0x188bf63d4 -[NSCondition waitUntilDate:] + 132
3   Foundation                             0x188bf923c -[NSConditionLock lockWhenCondition:beforeDate:] + 80
4   MIO                                    0x105229064 -[PluginLockPair scanPaths] + 112
5   Foundation                             0x188c14fb4 __NSThread__start__ + 716
6   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
7   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 8:: MIO Mounting Thread
0   libsystem_kernel.dylib                 0x1879f906c __psynch_cvwait + 8
1   libsystem_pthread.dylib                0x187a36628 _pthread_cond_wait + 1272
2   Foundation                             0x188bf63d4 -[NSCondition waitUntilDate:] + 132
3   Foundation                             0x188bf923c -[NSConditionLock lockWhenCondition:beforeDate:] + 80
4   MIO                                    0x105229064 -[PluginLockPair scanPaths] + 112
5   Foundation                             0x188c14fb4 __NSThread__start__ + 716
6   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
7   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 9:: MIO Mounting Thread
0   libsystem_kernel.dylib                 0x1879f906c __psynch_cvwait + 8
1   libsystem_pthread.dylib                0x187a36628 _pthread_cond_wait + 1272
2   Foundation                             0x188bf63d4 -[NSCondition waitUntilDate:] + 132
3   Foundation                             0x188bf923c -[NSConditionLock lockWhenCondition:beforeDate:] + 80
4   MIO                                    0x105229064 -[PluginLockPair scanPaths] + 112
5   Foundation                             0x188c14fb4 __NSThread__start__ + 716
6   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
7   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

Thread 10:: com.apple.helium-texture-finish
0   libsystem_kernel.dylib                 0x1879f906c __psynch_cvwait + 8
1   libsystem_pthread.dylib                0x187a365fc _pthread_cond_wait + 1228
2   Helium                                 0x106b709b0 TextureDeleteQueue::threadLoop() + 476
3   Helium                                 0x106b705f4 textureFinishThread(void*) + 36
4   libsystem_pthread.dylib                0x187a36034 _pthread_start + 136
5   libsystem_pthread.dylib                0x187a30e3c thread_start + 8

SPECS:

stevef243 commented 6 months ago

System Diagnostic https://drive.google.com/file/d/1M5r4Xs1vcFMdqgEgC4vXeKYzBrh-CLxV/view?usp=sharing

stevef243 commented 6 months ago
0   libobjc.A.dylib                   0x00000001816fd420 objc_msgSend + 32
1   com.apple.compressor.MediaServerAPI    0x000000028c6ebb4c CSimpleMediaProviderClientInProcess::renderFrameInto(long long, CRenderBufferRef const&) + 340
2   com.apple.compressor.StompTypes    0x000000028cb2fcd8 stomp::CMediaServerMediaDecoder::decodeFrame(long long, CRenderBufferRef const&, bool, bool) + 232
3   com.apple.compressor.StompTypes    0x000000028cb4f4c4 CHeliumFrameControlsProcessor::HeliumGetCVPixelBuffer(CMTime, __CVBuffer**, void*) + 556
4   com.apple.HeliumSenso             0x0000000101f7a9f8 InputJob::RenderCallback(HGRenderer*) + 208
5   com.apple.HeliumSenso             0x0000000101fe11b4 SOProvider::HandleJobStateExecuting(SOProvider::CustomJobData*, HGRenderer*) + 500
6   com.apple.HeliumSenso             0x0000000101fe19a8 SOProvider::UserJobNotifyFunc(HGUserJob*) + 180
7   com.apple.Helium                  0x0000000102bd7938 HGUserJob::CallNotifyFunc() + 48
8   com.apple.Helium                  0x0000000102c3f3d4 HGUserExecUnit::RunLoop() + 172
9   com.apple.Helium                  0x0000000102c3f318 StartUserExecUnitFunc(void*) + 20
10  libsystem_pthread.dylib           0x0000000181aca034 _pthread_start + 136
11  libsystem_pthread.dylib           0x0000000181ac4e3c thread_start + 8
joema4 commented 5 months ago

I am suspicious this might be related to the new 10.7.0 feature called "export segmentation", and apparently using CompressorKit.parallelizedTranscode. On certain Apple Silicon hardware platforms, export of certain H264 and HEVC timelines may attempt to use parallel encoding by concurrent use of multiple media engines. Each of these crashes have one or more threads doing that. That might be exposing a race condition. The threads doing parallel transcoding are not themselves crashing but they could easily mismanage a synchronization object that crashes other threads.

It would be interesting to try disabling “Allow export segmentation”, which is enabled by default in the Share window -- if conditions for export segmentations are met. Otherwise the option does not appear in the Share UI. If that prevents the problem, it would be an immediate workaround, plus it would tend to corroborate this as the cause.

See "Speed up exports with simultaneous processing in Final Cut Pro for Mac": https://support.apple.com/guide/final-cut-pro/speed-up-exports-with-simultaneous-processing-verd006aab15/mac

stevef243 commented 5 months ago

It could be. However, I fixed it by spending a lot of time going through every one of the nearly hundred clips, chacking where stabilisation was applied, and re-checking the stabilisation box. Unfortunately, this is also something that goes on for quite some time in FCP that it often can't even use the built-in features properly and then provides a error message without pointing out the clip with the issue is even worse.

stevef243 commented 5 months ago

I am suspicious this might be related to the new 10.7.0 feature called "export segmentation", and apparently using CompressorKit.parallelizedTranscode. On certain Apple Silicon hardware platforms, export of certain H264 and HEVC timelines may attempt to use parallel encoding by concurrent use of multiple media engines. Each of these crashes have one or more threads doing that. That might be exposing a race condition. The threads doing parallel transcoding are not themselves crashing but they could easily mismanage a synchronization object that crashes other threads.

It would be interesting to try disabling “Allow export segmentation”, which is enabled by default in the Share window -- if conditions for export segmentations are met. Otherwise the option does not appear in the Share UI. If that prevents the problem, it would be an immediate workaround, plus it would tend to corroborate this as the cause.

See "Speed up exports with simultaneous processing in Final Cut Pro for Mac": https://support.apple.com/guide/final-cut-pro/speed-up-exports-with-simultaneous-processing-verd006aab15/mac

Hm you could be right. again issue during export with FCP crashing once disabling simultaneous processing as well as deleting all renders and re-rendering it worked CleanShot 2024-01-17 at 12 28 42@2x

latenitefilms commented 5 months ago

If you still have the crash log (see here), can you show what Thread 82 says? When sharing crash logs it's important to show the actual crashed thread.

stevef243 commented 5 months ago

Final Cut Pro-2024-01-17-122827.crash.zip

latenitefilms commented 5 months ago

Here's the crashed thread in question:

Thread 82 Crashed:: com.apple.helium-render-queue-exec-unit-user
0   libobjc.A.dylib                   0x0000000189015420 objc_msgSend + 32
1   com.apple.compressor.MediaServerAPI    0x00000002831dfb4c CSimpleMediaProviderClientInProcess::renderFrameInto(long long, CRenderBufferRef const&) + 340
2   com.apple.compressor.StompTypes    0x0000000283c53cd8 stomp::CMediaServerMediaDecoder::decodeFrame(long long, CRenderBufferRef const&, bool, bool) + 232
3   com.apple.compressor.StompTypes    0x0000000283c734c4 CHeliumFrameControlsProcessor::HeliumGetCVPixelBuffer(CMTime, __CVBuffer**, void*) + 556
4   com.apple.HeliumSenso             0x000000010434a9f8 InputJob::RenderCallback(HGRenderer*) + 208
5   com.apple.HeliumSenso             0x00000001043b11b4 SOProvider::HandleJobStateExecuting(SOProvider::CustomJobData*, HGRenderer*) + 500
6   com.apple.HeliumSenso             0x00000001043b19a8 SOProvider::UserJobNotifyFunc(HGUserJob*) + 180
7   com.apple.Helium                  0x0000000104fa7938 HGUserJob::CallNotifyFunc() + 48
8   com.apple.Helium                  0x000000010500f3d4 HGUserExecUnit::RunLoop() + 172
9   com.apple.Helium                  0x000000010500f318 StartUserExecUnitFunc(void*) + 20
10  libsystem_pthread.dylib           0x00000001893e2034 _pthread_start + 136
11  libsystem_pthread.dylib           0x00000001893dce3c thread_start + 8

Are you sending to Compressor, or exporting via Final Cut Pro? Are you using a Compressor Share Destination?

stevef243 commented 5 months ago

nop straight from FCP Apple Device 4k segementation was enabled

stevef243 commented 5 months ago

Here's the crashed thread in question:

Thread 82 Crashed:: com.apple.helium-render-queue-exec-unit-user
0   libobjc.A.dylib                   0x0000000189015420 objc_msgSend + 32
1   com.apple.compressor.MediaServerAPI    0x00000002831dfb4c CSimpleMediaProviderClientInProcess::renderFrameInto(long long, CRenderBufferRef const&) + 340
2   com.apple.compressor.StompTypes    0x0000000283c53cd8 stomp::CMediaServerMediaDecoder::decodeFrame(long long, CRenderBufferRef const&, bool, bool) + 232
3   com.apple.compressor.StompTypes    0x0000000283c734c4 CHeliumFrameControlsProcessor::HeliumGetCVPixelBuffer(CMTime, __CVBuffer**, void*) + 556
4   com.apple.HeliumSenso             0x000000010434a9f8 InputJob::RenderCallback(HGRenderer*) + 208
5   com.apple.HeliumSenso             0x00000001043b11b4 SOProvider::HandleJobStateExecuting(SOProvider::CustomJobData*, HGRenderer*) + 500
6   com.apple.HeliumSenso             0x00000001043b19a8 SOProvider::UserJobNotifyFunc(HGUserJob*) + 180
7   com.apple.Helium                  0x0000000104fa7938 HGUserJob::CallNotifyFunc() + 48
8   com.apple.Helium                  0x000000010500f3d4 HGUserExecUnit::RunLoop() + 172
9   com.apple.Helium                  0x000000010500f318 StartUserExecUnitFunc(void*) + 20
10  libsystem_pthread.dylib           0x00000001893e2034 _pthread_start + 136
11  libsystem_pthread.dylib           0x00000001893dce3c thread_start + 8

Are you sending to Compressor, or exporting via Final Cut Pro? Are you using a Compressor Share Destination?

does not mean much to me. Does it give you some indication of what is going on?

joema4 commented 5 months ago

Steve, could you clarify whether "export segmentation" was enabled or disabled in the above crash? Your previous comment about this implied that with export segmentation disabled and cache deleted, the export did not crash. Is that correct? If so is that consistent?

The last crash log looks like it was doing parallelized encoding on threads 66, 67 and 68, which implies export segmentation. It appears FCP implements that by call the CompressorKit framework, even if you aren't using the Compressor app.

Thread 12 had a very long backtrace involving a lot of classes and methods in the Ozone framework. Frame 30 shows several classes and methods possibly related to VR360. Are any VR360 or similar effects used in this timeline?

As we proceed up the backtrace of thread 12 at frame 6, we see several TXT-related functions. Are any titles or similar effects used? Any info like this might help narrow down the source of the problem.

In frame 1 of thread 12, we see OZLockingGroup, which might manage synchronization for a group of related objects or data structures. The WriteSentry destructor suggests a write lock was held and is now being released.

All threads exist within the same address space, and FCP intermixes both UNIX-like "pthreads" Grand Central Dispatch threads. That may related to the source code evolution to the more abstract threading methods.

Chris and I have lots of software debugging experience, but fixing things like this usually requires achieving a reproducible failure scenario. It is difficult for a developer to reliably fix a problem solely from a crash log.

Is this crash-on-export problem consistent? Is it tied to a specific timeline? Does it only happen when export segmentation is enabled? Do any of my above comments ring any bells, ie VR360, titles or other text-based effects? Are you using any FCP built-in generators? If so, which ones?

If you duplicate the timeline, open the duplicate, delete the first half and export it, does that crash? What about the second half? Or is the crash on export intermittent, even with the full timeline?

There is a bug with the "Drifting" generator that can cause a hang or crash during rendering or export (varies based on Intel vs Apple Silicon, and type of GPU). I am still investigating that. I think it is isolated to that one generator but I'm not sure.

stevef243 commented 5 months ago

When it crashed export segmentation was enabled, I gave it 3 different attempts and it crashed every time. Unfortunately I forgot to try with segmentation disabled at the time

After deleting all rendered file, re-rendering everything the error did not come up and it exported fine with segmentation disabled.

Not sure what VR360 is but not used anywhere as far as I'm aware, however there are some text based effects used.

It has happened on a few occasions but it's not reproducible as such.

Very hard to do extensive testing as I'm under time constraints and need to finish this project before I travel again