Timing out with large history

[jtojnar]

I have a long history (history.xml has 71MB) and the the systemd service now takes about 3 minutes and 10 seconds to start. (I had to increase TimeoutSec key for org.gnome.GPaste.service, since the default ¿90? is insufficient.)

But what is worse, the GNOME Shell extension itself times out and the panel menu just shows (Couldn't connect to GPaste daemon), the following logged into journal:

JS ERROR: Gio.IOErrorEnum: Timeout was reached
_refresh/<@/run/current-system/sw/share/gnome-shell/extensions/GPaste@gnome-shell-extensions.gnome.org/indicator.js:264:37

Now I can have it connect by disabling and re-enabling the extension in the extension manager but doing it on every log-in is annoying.

It would be nice if we could optimize GPaste, or at least make the timeouts longer.

[jtojnar]

It actually have gotten worse with the switch to GNOME 43. Previously, only the extension was timing out, not the systemd service. And I noticed that when I connected with GDB, often the stack trace would contain

#0  0x00007f5bf2126de0 in _pcre2_valid_utf_8 () from /nix/store/qsx8cikb5fjsnm1lzaiiigamv7nj2417-pcre2-10.40/lib/libpcre2-8.so.0
#1  0x00007f5bf210b454 in pcre2_match_8 () from /nix/store/qsx8cikb5fjsnm1lzaiiigamv7nj2417-pcre2-10.40/lib/libpcre2-8.so.0
#2  0x00007f5bf31c9605 in g_match_info_next (match_info=0x588adb0, error=error@entry=0x7ffd573449e0) at ../glib/gregex.c:1088
#3  0x00007f5bf31cbd25 in g_regex_replace_eval (regex=<optimized out>, 
    string=0x67a7e00 "nts=POLLOUT}])\n[pid 19866] writev(7, [{iov_base=\"b\\0\\3\\0\\4\\0\\200\\4\", iov_len=8}, {iov_base=\"SYNC\", iov_len=4}, {iov_base=\"\", iov_len=0}], 3) = 12\n[pid 19866] poll([{fd=7, events=POLLIN}], 1, -1) = 1 ("..., string_len=6352057, start_position=0, match_options=G_REGEX_MATCH_DEFAULT, eval=eval@entry=0x7f5bf31c8b30 <literal_replacement>, user_data=0x7f5bf35a62e6, error=0x0)
    at ../glib/gregex.c:3419
#4  0x00007f5bf31cc0d9 in g_regex_replace_literal (regex=<optimized out>, string=<optimized out>, string_len=<optimized out>, start_position=<optimized out>, replacement=<optimized out>, 
    match_options=<optimized out>, error=0x0) at ../glib/gregex.c:3313
#5  0x00007f5bf35a0a43 in g_paste_util_replace () from /nix/store/29i4f7ygbdxlapakamkknmvr18m3an1v-gpaste-42.1/lib/libgpaste-2.so.0
#6  0x00007f5bf35a0e1f in g_paste_util_xml_decode () from /nix/store/29i4f7ygbdxlapakamkknmvr18m3an1v-gpaste-42.1/lib/libgpaste-2.so.0
#7  0x000000000040e250 in on_text ()
#8  0x00007f5bf31ba0ba in g_markup_parse_context_parse (context=0x1c279c0, text=<optimized out>, text_len=<optimized out>, error=0x0) at ../glib/gmarkup.c:1726
#9  0x000000000040f3d5 in g_paste_file_backend_read_history_file ()
#10 0x0000000000417052 in g_paste_storage_backend_read_history ()
#11 0x000000000040fcfc in g_paste_history_load_locked ()
#12 0x0000000000411bbd in g_paste_history_load ()
#13 0x000000000040b85e in g_paste_daemon_init ()
#14 0x00007f5bf32d1718 in g_type_create_instance (type=<optimized out>) at ../gobject/gtype.c:1931
#15 0x00007f5bf32b51b4 in g_object_new_internal (class=0x1b18410, params=params@entry=0x0, n_params=n_params@entry=0) at ../gobject/gobject.c:2226
#16 0x00007f5bf32b68ec in g_object_new_with_properties (object_type=29262272, n_properties=0, names=names@entry=0x0, values=values@entry=0x0) at ../gobject/gobject.c:2387
#17 0x00007f5bf32b74c1 in g_object_new (object_type=<optimized out>, first_property_name=<optimized out>) at ../gobject/gobject.c:2035
#18 0x000000000040dfd2 in g_paste_daemon_new ()
#19 0x0000000000408372 in main ()

and when I tried to measure the daemon with Sysprof, 81.46% of all samples would hit _pcre2_valid_utf_8.

Possibly this is a slow up caused by GLib switching to PCRE 2.

But this is only a single observation and it might just be that the history size increased over the threshold of systemd timeout between the time I last logged in (I tend to suspend my computer) and the time I switched to GNOME 43.

[jtojnar]

Actually, it looks like the freeze in regex happens every time I change the item in clipboard using the extension menu. That definitely did not use to happen:

#0  0x00007ff8d8026e00 in _pcre2_valid_utf_8 () from /nix/store/qsx8cikb5fjsnm1lzaiiigamv7nj2417-pcre2-10.40/lib/libpcre2-8.so.0
No symbol table info available.
#1  0x00007ff8d800b454 in pcre2_match_8 () from /nix/store/qsx8cikb5fjsnm1lzaiiigamv7nj2417-pcre2-10.40/lib/libpcre2-8.so.0
No symbol table info available.
#2  0x00007ff8d90e7605 in g_match_info_next (match_info=0x69f0800, error=error@entry=0x7ffcbd8b5b90) at ../glib/gregex.c:1088
        jit_status = <optimized out>
        prev_match_start = 1207844
        prev_match_end = 1207845
        opts = 0
        __func__ = "g_match_info_next"
#3  0x00007ff8d90e9d25 in g_regex_replace_eval (regex=<optimized out>, 
    string=0x765d770 " 2      0x22f3f30 DEBUG", ' ' <repeats 16 times>, "default gstvalue.c:2548:_priv_gst_value_parse_value: trying type name 'string'\n0:00:00.165027283     2      0x22f3f30 DEBUG", ' ' <repeats 14 times>, "structure gststructure.c"..., string_len=5459640, start_position=0, match_options=G_REGEX_MATCH_DEFAULT, eval=eval@entry=0x7ff8d90e6b30 <literal_replacement>, user_data=0x7ff8d94c42e8, error=0x0)
    at ../glib/gregex.c:3419
        match_info = 0x69f0800
        result = 0x225f520
        str_pos = 1207845
        done = 0
        tmp_error = 0x0
        __func__ = "g_regex_replace_eval"
#4  0x00007ff8d90ea0d9 in g_regex_replace_literal (regex=<optimized out>, string=<optimized out>, string_len=<optimized out>, start_position=<optimized out>, replacement=<optimized out>, 
    match_options=<optimized out>, error=0x0) at ../glib/gregex.c:3313
        __func__ = "g_regex_replace_literal"
#5  0x00007ff8d94bea43 in g_paste_util_replace () from /nix/store/29i4f7ygbdxlapakamkknmvr18m3an1v-gpaste-42.1/lib/libgpaste-2.so.0
No symbol table info available.
#6  0x00007ff8d94beeb8 in g_paste_util_xml_encode () from /nix/store/29i4f7ygbdxlapakamkknmvr18m3an1v-gpaste-42.1/lib/libgpaste-2.so.0
No symbol table info available.
#7  0x000000000040ee9b in g_paste_file_backend_write_history_file (self=<optimized out>, history_file_path=<optimized out>, history=0x50aaf20) at ../src/daemon/tmp/gpaste-file-backend.c:87
        kind = 0x41bdb1 "Text"
        special_values = 0x0
        item = 0x50aa570
        uuid = <optimized out>
        text = <optimized out>
        settings = <optimized out>
        history_file = 0x60a9320
        real_self = <optimized out>
        stream = 0x231f500
        __func__ = "g_paste_file_backend_write_history_file"
#8  0x0000000000417104 in g_paste_storage_backend_write_history (self=0x23219a0, name=<optimized out>, history=0x60a9660) at ../src/daemon/tmp/gpaste-storage-backend.c:67
        __func__ = "g_paste_storage_backend_write_history"
        history_file_path = 0x6987860 "/home/jtojnar/.local/share/GPaste/history.xml"
#9  0x000000000040f7a0 in g_paste_history_update (self=self@entry=0x22c9ec0, action=action@entry=G_PASTE_UPDATE_ACTION_REPLACE, target=G_PASTE_UPDATE_TARGET_ALL, position=position@entry=0)
    at ../src/daemon/tmp/gpaste-history.c:149
        priv = <optimized out>
        __func__ = "g_paste_history_update"
#10 0x00000000004104c0 in _g_paste_history_add (self=self@entry=0x22c9ec0, item=item@entry=0x2353260, new_selection=new_selection@entry=0) at ../src/daemon/tmp/gpaste-history.c:341
        __func__ = "_g_paste_history_add"
        priv = <optimized out>
        max_memory = <optimized out>
        history = <optimized out>
        election_needed = <optimized out>
        target = <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--c
#11 0x0000000000410f39 in g_paste_history_select (self=0x22c9ec0, uuid=uuid@entry=0x7ff8c40178e0 "c3cd84f1-bb7c-44c3-9a47-f88990564dd5") at ../src/daemon/tmp/gpaste-history.c:584
        __func__ = "g_paste_history_select"
        priv = 0x22c9e70
        locker = 0x22c9e70
        item = 0x2353260
#12 0x000000000040dca3 in g_paste_daemon_select (err=0x7ffcbd8b5d90, parameters=0x7ff8c4038d30, self=0x236a8c0) at ../src/daemon/tmp/gpaste-daemon.c:716
        priv = 0x236a800
        uuid = 0x7ff8c40178e0 "c3cd84f1-bb7c-44c3-9a47-f88990564dd5"
#13 g_paste_daemon_dbus_method_call (connection=<optimized out>, sender=sender@entry=0x7ff8c402caf0 ":1.273", object_path=object_path@entry=0x7ff8c402b350 "/org/gnome/GPaste", interface_name=interface_name@entry=0x7ff8c40179f0 "org.gnome.GPaste2", method_name=method_name@entry=0x7ff8c402cb50 "Select", parameters=parameters@entry=0x7ff8c4038d30, invocation=0x7ff8c403b470, user_data=0x236a8c0) at ../src/daemon/tmp/gpaste-daemon.c:937
        self = 0x236a8c0
        priv = <optimized out>
        answer = 0x0
        error = 0x0
        err = 0x0
#14 0x00007ff8d93295dd in call_in_idle_cb (user_data=0x7ff8c403b470) at ../gio/gdbusconnection.c:4997
        invocation = 0x7ff8c403b470
        vtable = <optimized out>
        registration_id = <optimized out>
        subtree_registration_id = <optimized out>
        ei = 0x6075260
        es = 0x0
        __func__ = "call_in_idle_cb"
#15 0x00007ff8d90d3874 in g_main_dispatch (context=0x21e0c30) at ../glib/gmain.c:3444
        dispatch = 0x7ff8d90cf8e0 <g_idle_dispatch>
        prev_source = 0x0
        begin_time_nsec = 0
        was_in_call = 0
        user_data = 0x7ff8c403b470
        callback = 0x7ff8d93294c0 <call_in_idle_cb>
        cb_funcs = <optimized out>
        cb_data = <optimized out>
        need_destroy = <optimized out>
        source = 0x7ff8c402eea0
        current = 0x21ebe80
        i = 0
        __func__ = "g_main_dispatch"
#16 g_main_context_dispatch (context=0x21e0c30) at ../glib/gmain.c:4162
No locals.
#17 0x00007ff8d90d3c18 in g_main_context_iterate (context=context@entry=0x21e0c30, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/gmain.c:4238
        max_priority = 2147483647
        timeout = -1
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = <optimized out>
        fds = 0x2387e30
        begin_time_nsec = 0
#18 0x00007ff8d90d3ccf in g_main_context_iteration (context=context@entry=0x21e0c30, may_block=may_block@entry=1) at ../glib/gmain.c:4303
        retval = <optimized out>
#19 0x00007ff8d92ff0ad in g_application_run (application=application@entry=0x21d40f0, argc=argc@entry=1, argv=argv@entry=0x7ffcbd8b6208) at ../gio/gapplication.c:2571
        arguments = 0x682e3e0
        status = 0
        context = 0x21e0c30
        acquired_context = <optimized out>
        __func__ = "g_application_run"
#20 0x000000000040848e in main (argc=1, argv=0x7ffcbd8b6208) at ../src/daemon/gpaste-daemon.c:163
        app = 0x21d40f0
        gapp = 0x21d40f0
        error = 0x0
        data = 0x2489f10
        g_paste_daemon = 0x236a8c0
        search_provider = 0x21e34e0
        bus = 0x231f9e0
        c_signals = {77, 78}
        usr1_data = {daemon = 0x236a8c0, app = 0x21d40f0}
        exit_status = <optimized out>

[Totto16]

I also have the same behavious now since GPaste 43 and Gnome 43, it takes about ~30 secs to switch from one entry the in clipboard using the extension menu. As far as I understand, this is an error in glib itself, and not GPaste, but it's really annoying, if you need an item and it takes, at least it feels like that, an eternity :(

[nlpsuge]

I have this issue long time ago. It makes GPaste unusable. I really like the gpaste-client.