Hi,
I use FreeFileSync under UBUNTU (GNOME shell) 19.10.
Problem : ~45 sec before opening
With UBUNTU(GNOME shell)18.04, instant opening.
An idea?
Regards
Start up hang on Ubuntu 19.10 (FFS 10.17)
- Posts: 4
- Joined: 21 Oct 2019
- Site Admin
- Posts: 7058
- Joined: 9 Dec 2007
Is this problem repeatable? If so I can create a debugging version, you would create a process dump while the hang occurs, and then send it to me for analysis.
- Posts: 306
- Joined: 7 Jan 2018
Ubuntu has started offering snap packages as the main method to install certain applications, particularly Google Chrome. The first time a snap is run, it has to download and/or initialize it, which sounds suspiciously like the 45 second delay you describe. I thought that was only for the very first use.
Can you determine if this application is running from a snap or the downloaded version from https://freefilesync.org/? I don't know enough specifics of how to install or list instsalled snaps, but you would remember if you're using the downloaded version or if you installed it through GNOME Software or some other software manager.
Can you determine if this application is running from a snap or the downloaded version from https://freefilesync.org/? I don't know enough specifics of how to install or list instsalled snaps, but you would remember if you're using the downloaded version or if you installed it through GNOME Software or some other software manager.
- Posts: 4
- Joined: 21 Oct 2019
The "problem" is systematic.
This application is running from a downloaded version from https://freefilesync.org/
This application is running from a downloaded version from https://freefilesync.org/
- Site Admin
- Posts: 7058
- Joined: 9 Dec 2007
I'm able to reproduce the start up hang on Ubuntu 19.10. FreeFileSync is hanging while waiting for GTK 2 function gtk_entry_get_layout_offsets() when it is called for the first time:
1 __GI___poll poll.c 29 0x7ffff7156c2f
2 ?? 0x7ffff745da3e
3 g_main_loop_run 0x7ffff745ddc3
4 g_dbus_connection_send_message_with_reply_sync 0x7ffff7705c85
5 ?? 0x7ffff770607f
6 g_dbus_connection_call_sync 0x7ffff77080f7
7 ?? 0x7ffff7708396
8 g_bus_get_sync 0x7ffff7708ae4
9 ?? 0x7ffff285c07f
10 g_type_create_instance 0x7ffff756e14d
11 ?? 0x7ffff7550345
12 g_object_new_with_properties 0x7ffff7551a45
13 g_object_new 0x7ffff75525f1
14 ?? 0x7ffff76785c4
15 ?? 0x7ffff7678ace
16 g_file_new_for_path 0x7ffff76625b2
17 ?? 0x7ffff30f3d8d
18 ?? 0x7ffff755016c
19 g_object_new_valist 0x7ffff7552278
20 g_object_new 0x7ffff75525cd
21 ibus_bus_new_async_client 0x7ffff30f1858
22 ?? 0x7ffff316a722
23 g_type_class_ref 0x7ffff756c201
24 g_object_new_with_properties 0x7ffff7551b38
25 g_object_new 0x7ffff75525f1
26 ibus_im_context_new 0x7ffff316b346
27 ?? 0x7ffff7b0f18f
28 ?? 0x7ffff7b0fb76
29 ?? 0x7ffff7b0fef7
30 gtk_im_context_get_preedit_string 0x7ffff7b0cd7b
31 ?? 0x7ffff7ab3bd5
32 ?? 0x7ffff7ab3cad
33 gtk_entry_get_layout_offsets 0x7ffff7ab8dca
34 wxControl::GTKGetEntryMargins control.cpp 389 0xe770ac
35 wxComboBox::DoGetSizeFromTextSize combobox.cpp 417 0xe756c8
36 wxControlBase::GetSizeFromTextSize control.h 114 0xe72780
37 wxChoice::DoGetBestSize choice.cpp 356 0xe72114
38 wxWindowBase::GetBestSize wincmn.cpp 940 0xf4e6f4
39 wxWindowBase::GetEffectiveMinSize wincmn.cpp 909 0xf4e53a
40 wxWindowBase::SetInitialSize wincmn.cpp 994 0xf4e946
41 wxControl::PostCreation control.cpp 113 0xe763a0
42 wxComboBox::Create combobox.cpp 161 0xe749c6
43 wxComboBox::wxComboBox combobox.h 42 0x7ebe46
44 fff::FolderHistoryBox::FolderHistoryBox folder_history_box.cpp 30 0x7ebe46
45 MainDialogGenerated::MainDialogGenerated string.h 3378 0x8a17e7
46 fff::MainDialog::MainDialog string.h 3378 0x955899
47 fff::MainDialog::create main_dlg.cpp 417 0x95e344
48 fff::MainDialog::create main_dlg.cpp 402 0x95ed79
49 runGuiMode application.cpp 693 0x4742a6
50 fff::Application::launch application.cpp 603 0x47ccc7
51 fff::Application::onEnterEventLoop application.cpp 339 0x47e44d
52 wxAppConsoleBase::HandleEvent appbase.cpp 657 0x10844d2
53 wxAppConsoleBase::CallEventHandler appbase.cpp 669 0x108454a
54 wxEvtHandler::ProcessEventIfMatchesId event.cpp 1415 0x11754cc
55 wxEvtHandler::SearchDynamicEventTable event.cpp 1887 0x11762ba
56 wxEvtHandler::TryHereOnly event.cpp 1608 0x117599e
57 wxEvtHandler::TryBeforeAndHere event.h 3925 0x1177173
58 wxEvtHandler::ProcessEventLocally event.cpp 1545 0x11757e1
59 wxEvtHandler::ProcessEvent event.cpp 1518 0x1175775
60 wxEvtHandler::ProcessPendingEvents event.cpp 1382 0x1175338
61 wxAppConsoleBase::ProcessPendingEvents appbase.cpp 566 0x1084138
62 wxApp::DoIdle app.cpp 151 0xe2e6d2
63 wxapp_idle_callback app.cpp 99 0xe2e538
64 g_main_context_dispatch 0x7ffff745d71e
65 ?? 0x7ffff745dad0
66 g_main_loop_run 0x7ffff745ddc3
67 gtk_main 0x7ffff7b25092
68 wxGUIEventLoop::DoRun evtloop.cpp 64 0xfecec1
69 wxEventLoopBase::Run evtloopcmn.cpp 90 0x10b4712
70 wxAppConsoleBase::MainLoop appbase.cpp 380 0x108392e
71 wxAppConsoleBase::OnRun appbase.cpp 301 0x1083641
72 wxAppBase::OnRun appcmn.cpp 335 0xead99d
73 fff::Application::OnRun application.cpp 375 0x4791bb
74 wxEntry init.cpp 507 0x10dfc1f
75 wxEntry init.cpp 519 0x10dfd0a
76 main application.cpp 51 0x474288
- Site Admin
- Posts: 7058
- Joined: 9 Dec 2007
The final part of the puzzle: The worker thread that main is waiting for (see 1 __GI___poll ):
1 __lll_lock_wait lowlevellock.c 52 0x7ffff73b70b0
2 __GI___pthread_mutex_lock pthread_mutex_lock.c 115 0x7ffff73af1f1
3 g_type_add_interface_static 0x7ffff756e501
4 ?? 0x7ffff7695e24
5 g_simple_async_result_get_type 0x7ffff7695f15
6 g_async_result_legacy_propagate_error 0x7ffff7647a04
7 ?? 0x7ffff767a424
8 ?? 0x7ffff76ab029
9 ?? 0x7ffff76ab06d
10 g_main_context_dispatch 0x7ffff745d71e
11 ?? 0x7ffff745dad0
12 g_main_loop_run 0x7ffff745ddc3
13 ?? 0x7ffff771459a
14 ?? 0x7ffff7487111
15 start_thread pthread_create.c 479 0x7ffff73ac669
16 clone clone.S 95 0x7ffff7163323
- Posts: 4
- Joined: 21 Oct 2019
Bravo !
- Site Admin
- Posts: 7058
- Joined: 9 Dec 2007
Here's what's going wrong:
26 ibus_im_context_new calls g_object_new:
https://github.com/ibus/ibus/blob/1.5.y/client/gtk2/ibusimcontext.c#L233
Internally this initialization winds up calling g_type_class_ref() which is holding the global class_init_rec_mutex lock.
https://gitlab.gnome.org/GNOME/glib/blob/2.62.1/gobject/gtype.c#L2908
Next it tries to load a file:
g_file_new_for_path() OTOH requires a GVfs* to use the path upon:
https://gitlab.gnome.org/GNOME/glib/blob/2.62.1/gio/gvfs.c#L348
_g_io_module_get_default() buffers the result, but upon first entry it ends spinning up a worker thread:
https://gitlab.gnome.org/GNOME/glib/blob/2.62.1/gio/giomodule.c#L879
The worker thread calls g_type_add_interface_static() which also tries to acquire class_init_rec_mutex! The lock is recursive, but this doesn't help at all since we're in another thread.
=> DEADLOCK!
It's unclear who's to blame, ibus or GLib, probably both: ibus initialization ends up loading a config file while still holding the class_init_rec_mutex lock, which ignores good practice of avoiding callbacks while locks are held. GLib OTOH tries to be clever by using a recursive lock, but then runs initialization on a worker thread, making the deadlock possible in first place.
My guess is that this bug slipped through ibus testing because file load operations (g_file_new_for_path()) often happen before the first call to ibus initialization, thous g_vfs_get_default() can run first and globally buffer the result outside the class_init_rec_mutex lock.
Workaround fixing this bug has been implemented for FreeFileSync 10.18:
https://www.mediafire.com/file/9dgmrbdk4tqbrgn/FreeFileSync_10.18_beta_Linux.tar.gz
26 ibus_im_context_new calls g_object_new:
GObject *obj = g_object_new (IBUS_TYPE_IM_CONTEXT, NULL);
Internally this initialization winds up calling g_type_class_ref() which is holding the global class_init_rec_mutex lock.
https://gitlab.gnome.org/GNOME/glib/blob/2.62.1/gobject/gtype.c#L2908
Next it tries to load a file:
g_file_new_for_path //for file path ibus_get_socket_path()
GVfs* g_vfs_get_default(void)
{
if (GLIB_PRIVATE_CALL (g_check_setuid) ())
return g_vfs_get_local ();
return _g_io_module_get_default (G_VFS_EXTENSION_POINT_NAME,
"GIO_USE_VFS",
(GIOModuleVerifyFunc)g_vfs_is_active);
}
_g_io_module_get_default() buffers the result, but upon first entry it ends spinning up a worker thread:
https://gitlab.gnome.org/GNOME/glib/blob/2.62.1/gio/giomodule.c#L879
The worker thread calls g_type_add_interface_static() which also tries to acquire class_init_rec_mutex! The lock is recursive, but this doesn't help at all since we're in another thread.
=> DEADLOCK!
It's unclear who's to blame, ibus or GLib, probably both: ibus initialization ends up loading a config file while still holding the class_init_rec_mutex lock, which ignores good practice of avoiding callbacks while locks are held. GLib OTOH tries to be clever by using a recursive lock, but then runs initialization on a worker thread, making the deadlock possible in first place.
My guess is that this bug slipped through ibus testing because file load operations (g_file_new_for_path()) often happen before the first call to ibus initialization, thous g_vfs_get_default() can run first and globally buffer the result outside the class_init_rec_mutex lock.
Workaround fixing this bug has been implemented for FreeFileSync 10.18:
https://www.mediafire.com/file/9dgmrbdk4tqbrgn/FreeFileSync_10.18_beta_Linux.tar.gz
- Site Admin
- Posts: 7058
- Joined: 9 Dec 2007
- Posts: 4
- Joined: 21 Oct 2019
Cool,
It works again with this new beta version : instant opening
Thank you !
It works again with this new beta version : instant opening
Thank you !