Start up hang on Ubuntu 19.10 (FFS 10.17)

[sorbus]

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

[Zenju]

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.

[bgstack15]

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.

[sorbus]

The "problem" is systematic.
This application is running from a downloaded version from https://freefilesync.org/

[Zenju]

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


[Zenju]

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


[sorbus]

Bravo !

[Zenju]

Here's what's going wrong:

26 ibus_im_context_new calls g_object_new:

GObject *obj = g_object_new (IBUS_TYPE_IM_CONTEXT, NULL);


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 //for file path ibus_get_socket_path()


g_file_new_for_path() OTOH requires a GVfs* to use the path upon:

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);
}


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

[Zenju]

Probably related:
type initialisation deadlock in GObject (Opened 7 years ago)
Status: Open

:>

[sorbus]

Cool,
It works again with this new beta version : instant opening
Thank you !