Hi, preview_start=0, preview_end=-1 means that preview is not active this is the result from the constructor: localsession.C:92 There is no difference at the event layer between single and double clicks. The ButtonPress/ButtonRelease events have timestamps, and if the button nums matches and it is "really" quick (300 ms, per bcresources.C:841) then it is a double click. If you are seeing a deadlock type hang, (a race between locks) the best way I know to try to identify the culprits is to: 1) start cin in gdb 2) run the session which hangs until it hangs. 3) hit ^C, which will be intercepted by gdb. 4) enter: "p dump()" This will produce a lock trace table dump. You can do this at any time. On an idle system it looks like this: (gdb) p dump() signal_entry: lock table size=22 0x5b098b0 VIconThread::draw_lock, VIconThread::run 0 0x7fffe0ab2700 0x6117a10 CWindowTool::input_lock, CWindowTool::run 0x7fffdb7fe700 0x625f340 PlaybackEngine::output_lock, PlaybackEngine::run 0x7fffdaffd700 0x6265ce0 BC_DialogThread::active_lock, BC_DialogThread::run 0x7fffda7fc700 * 0x7fffd41c4dc0 PlaybackEngine::output_lock, PlaybackEngine::run 0x7fffd97fa700 0x66924d0 RecordSetChannel::change_channel, (null) 0x7fffcbfff700 0x6698880 RecordCutAdsStatus::wait_lock, RecordCutAdsStatus::run 0x7fffcb7fe700 0x67a52a0 ChannelInfo::scan_lock, (null) 0x7fffcaffd700 0x67a68d0 SWindow::swin_lock, (null) 0x7fffca7fc700 0x69dafb0 MainIndexes::input_lock, MainIndexes::run 1 0x7fffc8ff9700 0x648a2d0 ResourceThread::draw_lock, ResourceThread::run 0x7fffd2ffd700 0x4926280 BC_Synchronous::next_command, BC_Synchronous::run 0x7fffb2ffd700 0x4923590 MWindow::run_lock, MWindow::run 0x7ffff6d43840 * 0x7fffd40028c0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffda7fc700 lock_items: 20 lock_frees: 3 $1 = void The columns are lock_addr, lock_name, lock_loc, thread_id The locks with the * on the end are waiting (maybe hung). == To see what that thread is doing, use: "thr find <thread_id>" like this: (gdb) thr find 0x7ffff6d43840 Thread 1 has target id 'Thread 0x7ffff6d43840 (LWP 184411)' == Then switch to that thread like this: (gdb) thr 1 [Switching to thread 1 (Thread 0x7ffff6d43840 (LWP 184411))] #0 0x00007ffff7cafd45 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 == Then get a backtrace to see what is on the stack. (gdb) thr 1 (gdb) bt #0 0x00007ffff7cafd45 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000d9679a in Condition::lock (this=0x6267920, location=0x2bc1b07 "BC_WindowBase::get_event") at condition.C:64 #2 0x0000000000d8e61b in BC_WindowBase::get_event (this=0x6265f50) at bcwindowbase.C:4557 #3 0x0000000000d839f1 in BC_WindowBase::dispatch_event (this=0x6265f50) at bcwindowbase.C:917 #4 0x0000000000d82ff3 in BC_WindowBase::run_window (this=0x6265f50) at bcwindowbase.C:741 #5 0x0000000000b9851f in MWindow::run (this=0x7fffffffbc80) at mwindow.C:2898 #6 0x0000000000b50096 in main (argc=1, argv=0x7fffffffd798) at main.C:389 In this case, it is simply a lock used by the main program running mwindow, to wait for it to finish before destroying a bunch of stuff. It stays locked while the program runs, until it is release by the mwindow so the destructor can lock it, which prevents the destructor from running until mwindow is done. Not a hang. A live session lock trace table is more complex, this one has a playback active: [Detaching after vfork from child process 184602] ^C Thread 1 "ci" received signal SIGINT, Interrupt. 0x00007ffff7cafd45 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 Missing separate debuginfos, use: dnf debuginfo-install alsa-plugins-pulseaudio-1.2.2-1.fc31.x86_64 (gdb) p dump() signal_entry: lock table size=27 0x5b098b0 VIconThread::draw_lock, VIconThread::run 0 0x7fffe0ab2700 0x6117a10 CWindowTool::input_lock, CWindowTool::run 0x7fffdb7fe700 0x6265ce0 BC_DialogThread::active_lock, BC_DialogThread::run 0x7fffda7fc700 * 0x66924d0 RecordSetChannel::change_channel, (null) 0x7fffcbfff700 0x6698880 RecordCutAdsStatus::wait_lock, RecordCutAdsStatus::run 0x7fffcb7fe700 0x67a52a0 ChannelInfo::scan_lock, (null) 0x7fffcaffd700 0x67a68d0 SWindow::swin_lock, (null) 0x7fffca7fc700 0x4926280 BC_Synchronous::next_command, BC_Synchronous::run 0x7fffb2ffd700 0x4923590 MWindow::run_lock, MWindow::run 0x7ffff6d43840 * 0x7fffd41c4dc0 PlaybackEngine::output_lock, PlaybackEngine::run 0x7fffd97fa700 0x69dafb0 MainIndexes::input_lock, MainIndexes::run 1 0x7fffc8ff9700 0x625f340 PlaybackEngine::output_lock, PlaybackEngine::run 0x7fffdaffd700 0x67a7360 BC_Repeater::pause_lock, BC_Repeater::run 0x7fffc9ffb700 0x7fffdaffd700 0x648a2d0 ResourceThread::draw_lock, ResourceThread::run 0x7fffd2ffd700 0x7fff78005140 AudioDevice::arm_lock, AudioDevice::arm_buffer 0x7fff68ff9700 0x648a9f0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffd1ffb700 0x5b78cd0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffe1c9b700 0x5baae00 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffc37fe700 0x67b2560 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffc27fc700 0x69dfd10 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffb3fff700 0x6267920 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7ffff6d43840 0x7fffd40028c0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffda7fc700 0x648a9f0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffd1ffb700 lock_items: 22 lock_frees: 5 AudioALSA::write_buffer err -32(Broken pipe) at sample 163840 $2 = void Here you see the PlaybackEngine, BC_Synchronous (opengl video), AudioDevice (audio), and a bunch of idle threads. Still a normal situation. If you find a "bad" guy, it will usually be because the XDisplayLock function is waiting on a locked window, and that window lock is held by a thread that wants a lock that the current task owns. A waits on B, B waits on A. deadlock. Here I used gdb to errantly set a lock on the composer canvas window (gdb) p window->lock_window("bug test lock") $4 = 0 (gdb) c Continuing. and then I tried playback, which hangs, and I interrupt, and see this: (gdb) p dump() signal_entry: lock table size=28 0x5b098b0 VIconThread::draw_lock, VIconThread::run 0 0x7fffe0ab2700 0x6117a10 CWindowTool::input_lock, CWindowTool::run 0x7fffdb7fe700 0x6265ce0 BC_DialogThread::active_lock, BC_DialogThread::run 0x7fffda7fc700 * 0x66924d0 RecordSetChannel::change_channel, (null) 0x7fffcbfff700 0x6698880 RecordCutAdsStatus::wait_lock, RecordCutAdsStatus::run 0x7fffcb7fe700 0x67a52a0 ChannelInfo::scan_lock, (null) 0x7fffcaffd700 0x67a68d0 SWindow::swin_lock, (null) 0x7fffca7fc700 0x4926280 BC_Synchronous::next_command, BC_Synchronous::run 0x7fffb2ffd700 0x4923590 MWindow::run_lock, MWindow::run 0x7ffff6d43840 * 0x7fffd41c4dc0 PlaybackEngine::output_lock, PlaybackEngine::run 0x7fffd97fa700 0x69dafb0 MainIndexes::input_lock, MainIndexes::run 1 0x7fffc8ff9700 0x67a7360 BC_Repeater::pause_lock, BC_Repeater::run 0x7fffc9ffb700 0x7fffdaffd700 0x5baae00 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffc37fe700 0x5f86cd8 Cinelerra: Compositor, BC_Repeater::run 0x7fffc17fa700 0x648a2d0 ResourceThread::draw_lock, ResourceThread::run 0x7fffd2ffd700 0x7fff78007be0 AudioDevice::play_lock, AudioDevice::run 1 0x7fff4ffff700 0x5f86cd8 Cinelerra: Compositor, VDeviceX11::open_output 0x7fffdaffd700 0x648a9f0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffd1ffb700 0x67b2560 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffc27fc700 0x5b78cd0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffe1c9b700 0x69dfd10 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffb3fff700 0x6267920 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7ffff6d43840 0x7fffd40028c0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffda7fc700 0x648a9f0 BC_WindowBase::event_condition, BC_WindowBase::get_event 0x7fffd1ffb700 lock_items: 23 lock_frees: 5 $7 = void Because I had a good idea where to look (drawing on the locked canvas) I tried the VDeviceX11::open_output locked thread: (gdb) thr find 0x7fffdaffd700 Thread 8 has target id 'Thread 0x7fffdaffd700 (LWP 184434)' (gdb) thr 8 [Switching to thread 8 (Thread 0x7fffdaffd700 (LWP 184434))] #0 0x00007ffff7cafd45 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 (gdb) bt #0 0x00007ffff7cafd45 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x00007ffff7e97045 in _XDisplayLockWait () from /lib64/libX11.so.6 #2 0x00007ffff7e974ed in _XLockDisplay () from /lib64/libX11.so.6 #3 0x00007ffff7e96ebb in XLockDisplay () from /lib64/libX11.so.6 #4 0x0000000000d8adf3 in BC_WindowBase::lock_window (this=0x5f86cd0, location=0x2b9b520 "VDeviceX11::open_output") at bcwindowbase.C:3322 #5 0x0000000000d8ada5 in BC_WindowBase::lock_window (this=0x60fbee0, location=0x2b9b520 "VDeviceX11::open_output") at bcwindowbase.C:3313 #6 0x0000000000a2c470 in Canvas::lock_canvas (this=0x60fbe00, loc=0x2b9b520 "VDeviceX11::open_output") at canvas.C:94 #7 0x0000000000ca2d55 in VDeviceX11::open_output (this=0x7fff78023110) at vdevicex11.C:103 #8 0x0000000000ca6c59 in VideoDevice::open_output (this=0x7fff7800da10, config=0x7fff78033bb0, rate=29.9700298, out_w=352, out_h=240, output=0x60fbe00, single_frame=0) at videodevice.C:689 #9 0x0000000000c244d6 in RenderEngine::open_output (this=0x7fff7800a2d0) at renderengine.C:328 #10 0x0000000000c23e7c in RenderEngine::arm_command (this=0x7fff7800a2d0, command=0x5bb7f20) at renderengine.C:180 #11 0x0000000000bc1db3 in PlaybackEngine::arm_render_engine (this=0x4a47220) at playbackengine.C:147 #12 0x0000000000bc282d in PlaybackEngine::run (this=0x4a47220) at playbackengine.C:412 #13 0x0000000000da57bd in Thread::entrypoint (parameters=0x4a47220) at thread.C:65 #14 0x00007ffff7ca94e2 in start_thread () from /lib64/libpthread.so.0 #15 0x00007ffff75336d3 in clone () from /lib64/libc.so.6 You can see it is waiting on the XDisplayLock, probably because the composer is hosed and has it. You can see the XDisplayLock owner (possible bad guy) like this: (gdb) up #1 0x00007ffff7e97045 in _XDisplayLockWait () from /lib64/libX11.so.6 (gdb) #2 0x00007ffff7e974ed in _XLockDisplay () from /lib64/libX11.so.6 (gdb) #3 0x00007ffff7e96ebb in XLockDisplay () from /lib64/libX11.so.6 (gdb) #4 0x0000000000d8adf3 in BC_WindowBase::lock_window (this=0x5f86cd0, location=0x2b9b520 "VDeviceX11::open_output") at bcwindowbase.C:3322 3322 XLockDisplay(top_level->display); (gdb) p /x top_level->display_lock_owner $8 = 0x7fff6b7fe700 (gdb) thr find 0x7fff6b7fe700 Thread 83 has target id 'Thread 0x7fff6b7fe700 (LWP 184684)' (gdb) bt #0 0x00007ffff7cafd45 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x00007ffff7e97045 in _XDisplayLockWait () from /lib64/libX11.so.6 #2 0x00007ffff7e974ed in _XLockDisplay () from /lib64/libX11.so.6 #3 0x00007ffff7e96ebb in XLockDisplay () from /lib64/libX11.so.6 #4 0x0000000000d8adf3 in BC_WindowBase::lock_window (this=0x5f86cd0, location=0x2b9b520 "VDeviceX11::open_output") at bcwindowbase.C:3322 #5 0x0000000000d8ada5 in BC_WindowBase::lock_window (this=0x60fbee0, location=0x2b9b520 "VDeviceX11::open_output") at bcwindowbase.C:3313 #6 0x0000000000a2c470 in Canvas::lock_canvas (this=0x60fbe00, loc=0x2b9b520 "VDeviceX11::open_output") at canvas.C:94 #7 0x0000000000ca2d55 in VDeviceX11::open_output (this=0x7fff78023110) at vdevicex11.C:103 #8 0x0000000000ca6c59 in VideoDevice::open_output (this=0x7fff7800da10, config=0x7fff78033bb0, rate=29.9700298, out_w=352, out_h=240, output=0x60fbe00, single_frame=0) at videodevice.C:689 #9 0x0000000000c244d6 in RenderEngine::open_output (this=0x7fff7800a2d0) at renderengine.C:328 #10 0x0000000000c23e7c in RenderEngine::arm_command (this=0x7fff7800a2d0, command=0x5bb7f20) at renderengine.C:180 #11 0x0000000000bc1db3 in PlaybackEngine::arm_render_engine (this=0x4a47220) at playbackengine.C:147 #12 0x0000000000bc282d in PlaybackEngine::run (this=0x4a47220) at playbackengine.C:412 #13 0x0000000000da57bd in Thread::entrypoint (parameters=0x4a47220) at thread.C:65 #14 0x00007ffff7ca94e2 in start_thread () from /lib64/libpthread.so.0 #15 0x00007ffff75336d3 in clone () from /lib64/libc.so.6 this can be a good way to narrow down the locks and threads that are in play during a deadlock. It is a good idea to very carefully record what you are typing and/or mousing (the xevent stream drives all of this). There is no magic bullet to fix a deadlock that I know. If you can get some p dump()'s maybe I can help narrow it down, or maybe the problem will be more obvious. gg On Mon, Mar 2, 2020 at 11:43 AM Andrew Randrianasulu < [email protected]> wrote:
Hi, all
So, I tried to debug non-working/freezing timebar in Compositor ....
BC_WindowBase::dispatch_event 956 Cinelerra: Составитель 0xe277658 6 (MotionNotify) BC_WindowBase::dispatch_event this=0xe3d9b40 1360 BC_WindowBase::dispatch_event 956 Cinelerra: Составитель 0xdae2758 4 (ButtonPress) CTimeBar:pixel_to_Position CTimeBar: pixel, 110 CTimebar:pix_to_pos: Got EDL! CTimebar:pix_to_pos: prev_start 0.000000, prev_end -1.000000 CTimeBar:pixel_to_pos start, 0, end 0 BC_WindowBase::dispatch_event this=0xe2d10450 1360 BC_WindowBase::dispatch_event this=0xe849748 1360 BC_WindowBase::dispatch_event this=0xe582418 1360 BC_WindowBase::dispatch_event this=0xe1480d0 1360 BC_WindowBase::dispatch_event this=0xe920510 1360 BC_WindowBase::dispatch_event this=0xe582418 1360
additional printfs added by me:
diff --git a/cinelerra-5.1/cinelerra/ctimebar.C b/cinelerra-5.1/cinelerra/ctimebar.C index b9fb0bd..e0a1ee5 100644 --- a/cinelerra-5.1/cinelerra/ctimebar.C +++ b/cinelerra-5.1/cinelerra/ctimebar.C @@ -59,23 +59,30 @@ EDL* CTimeBar::get_edl()
void CTimeBar::draw_time() { + printf("CTimeBar::draw_time before draw_range"); draw_range(); + printf("CTimeBar::draw_time after draw_range"); }
double CTimeBar::pixel_to_position(int pixel) { + printf("CTimeBar:pixel_to_Position \n"); + printf("CTimeBar: pixel, %i \n", pixel); double start = 0, end = get_edl_length(); EDL *edl = get_edl(); if( edl ) { + printf("CTimebar:pix_to_pos: Got EDL!\n"); double preview_start = edl->local_session->preview_start; double preview_end = edl->local_session->preview_end; + printf("CTimebar:pix_to_pos: prev_start %f, prev_end %f \n", preview_start, preview_end); if( preview_end >= 0 || preview_start > 0 ) start = preview_start; if( preview_end >= 0 && preview_end < end ) end = preview_end; } if( start > end ) start = end; + printf("CTimeBar:pixel_to_pos start, %d, end %d \n" , start, end); return start + (double)pixel * (end - start) / get_w(); }
Hm, so preview end for some reason become negative??? -- Cin mailing list [email protected] https://lists.cinelerra-gg.org/mailman/listinfo/cin