Gajim interface is irresponsive during lengthy network operations

[dottedmag@…]

Seems that Gajim's interface is synchronous with network operations: many lengthy network operations (connecting to slow server, fetching lot of conferences names from the big server, such as jabber.ru) freeze the interface.

[patrys@…]

They are afraid of threading :/

[dottedmag@…]

There are some real obstacles, such as FreeBSD with it's unreliable and

crashy threads (or even FreeBSD 4.11 with userspace threads with scheduler which is unable to schedule threads during syscalls).

However, there is plenty of ways how to integrate GUI main loop with asynchronous I/O. Simpliest is the gtk.main_iteration() + select.select() with reasonable timeouts.

[dkirov]

Starting from 0.10 Gajim uses asynchronous api for network I/O. This

includes glib main loop + glib routines for polling events (depending on the platform poller could be select, poll or epoll).

The only place where a blocking action may occur is switching a socket to ssl mode, since python doesn't support doing it with sockets in nonblocking mode. Hopwever, I doubt that this is the place where you experienced the freeze.

"fetching lot of conferences names" - this is a problem of pygtk/gajim not being able to display large tree model and it has nothing to do with networking. AFAIK there was a ticket about that.

Can you try to run it in verbose mode and see what are the last printed debug message before each freeze?

[dottedmag@…]

Oh, sorry for the confusion. Networking clearly is not the bottleneck

here.

Three spotted blocking UI actions are fetching big list of conferences, fetching big roster and shutting down Gajim. All of them are not network- bound: fetching conferences and roster blocks UI after network exchange, and there is no clear information in verbose log about what blocks Gajim on shutdown (and there is little of network conversation on this stage).

Seems that this bug may be closed or duplicated to the "slow tree model rendering" bug.

[dkirov]

Let's keep it open, because long conference hungout was supposed to be

fixed months ago. Roster items are shown one by one, so this bottleneck is something new and unexpected! In some occasions Gajim stores each vcard and avatar to disc, which in your case may be slow. Can you try to see if some of your contacts have long avatars? We should find out in which part is the bottleneck: parsing stanzas, writing vcards/avatars to disc, or displaying roster items.

About shutdown: there is a delay when waiting to send offline presence stanza and stream end message to server. Again this cannot cause the freeze - network writes are asynchronous. Just before exit Gajim stores its .config file, which is blocking file i/o operation and may look slow. Combined with roster redraw and closing and cleaning all resources. These are several CPU bound operations, being executed one after another and as a whole may cause high cpu usage for several seconds, which may lead to UI freeze. Usually, on slow machines most of the programs behave the same way, esp. if there is write-to-disc.

[patrys@…]

I get a long (and I mean 5+ seconds) freeze each time a new conversation

is open (or after the tab was closed).

Steps to reproduce:

1. open gajim
2. switch to tabbed chat
3. wait for any person to say anything
4. click the tray icon
5. go get some coffee while the app is frozen
6. see that the message was irrelevant and close the tab
7. get another message from the same person
8. drink the coffee while...

And so on. I have around 150-200 people on my roster.

[dkirov]

In this case delay can only because of disk i/o. I never managed to test

how Gajim behaves with long sqlite db. Can you try the following test:

• backup sqlite database file and config file

   mv ~/.gajim/config /somebackupdir/
   mv ~/.gajim/logs.db /somebackupdir/
   ....
  

• start gajim and register your account. Try to see if the delay is

reproducable.

• move back the old config and database

   mv /somebackupdir/config ~/.gajim/
   mv /somebackupdir/logs.db ~/.gajim/
  

[patrys@…]

Still not perfect, but better. It amuses me to see that selecting 3 last

entries from the DB takes us much time (I believe it's caused by displaying the last lines from chat history - btw, there is a bug about it

• remove the small font as it's unreadable).

More info:

 [patrys@meaw .gajim]$ ls -lh config logs.db
 -rw-------  1 patrys users 17K 2006-08-09 21:36 config
 -rw-------  1 patrys users 34M 2006-08-09 21:51 logs.db

[dkirov]

Also you can try to toogle these ACE options:

{{ show_avatar_in_chat show_avatar_in_roster }}} There is space for improvements in both disk/db operations and model display, but first it will be good to be sure where exactly is the problem.

If it is in sqlite I propose to automatically split logs per month (different file for different month). This will bring a little delay in history viewers, but IMO casual chat messages speed is more important than history.

[dottedmag@…]

Roster items are shown one by one, so this bottleneck is something new and

unexpected!

Logs from startup:

 DEBUG: roster       ok    Setting roster item
 159371527@icq.jabber.dottedmag.net...
 --- gajim stops here. No visible disk I/O at the point.
 DEBUG: dispatcher   start Plugging <common.xmpp.dispatcher_nb.Dispatcher
 instance at 0xa6db40ec> into <common.xmpp.client_nb.NonBlockingClient
 instance at 0xa6e1440c>
 DEBUG: dispatcher   info  Registering namespace "unknown"
 DEBUG: dispatcher   info  Registering protocol "unknown" as
 common.xmpp.protocol.Protocol(unknown)
 DEBUG: dispatcher   info  Registering protocol "default" as
 common.xmpp.protocol.Protocol(unknown)
 DEBUG: dispatcher   info  Registering namespace
 "http://etherx.jabber.org/streams"
 DEBUG: dispatcher   info  Registering protocol "unknown" as
 common.xmpp.protocol.Protocol(http://etherx.jabber.org/streams)

About shutdown

There at least two problems:

• several accounts are shut down not in parallel, but one-by-one.
• shutdown of each account is slow. From the logs:

 13 Aug 2006 12:45:11 Gajim: disconnectedReconnCB
 -- here is the first stop during shutdown. No disk I/O is performed at
 this point. ~4 seconds
 DEBUG: roster       stop  Plugging
 <common.xmpp.roster_nb.NonBlockingRoster instance at 0xa6b94aec> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa6e1440c>.
 DEBUG: gen_auth     stop  Plugging <common.xmpp.auth_nb.NonBlockingNonSASL
 instance at 0xa6dc614c> out of <common.xmpp.client_nb.NonBlockingClient
 instance at 0xa6e1440c>.
 DEBUG: sasl         stop  Plugging <common.xmpp.auth_nb.SASL instance at
 0xa6dc694c> out of <common.xmpp.client_nb.NonBlockingClient instance at
 0xa6e1440c>.
 DEBUG: nonblockingt stop  Plugging
 <common.xmpp.transports_nb.NonBlockingTLS instance at 0xa6db470c> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa6e1440c>.
 DEBUG: dispatcher   stop  Plugging <common.xmpp.dispatcher_nb.Dispatcher
 instance at 0xa6db40ec> out of <common.xmpp.client_nb.NonBlockingClient
 instance at 0xa6e1440c>.
 DEBUG: socket       stop  Plugging
 <common.xmpp.transports_nb.NonBlockingTcp instance at 0xa6e1438c> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa6e1440c>.
 -- here is the another stop, again, without any disk I/O. ~2 seconds

[dkirov]

Logs from startup are mixed logs from two accounts, or there is something

really wrong with gajim. Dispatcher is plugged long before getting and setting roster items. If this is a log from two accounts then you probably experience the stop mentioned in comment3: switching a socket to ssl mode.

Setting show_avatar_in_roster=False and comparing the results can give some additional hints. If the freeze time is almost the same then the problem is not in filling and drawing roster model.

I cannot reproduce the stop from shutdown. On my machine this is done immediately, even with slow internet connection, or highly loaded CPU. I'll try to test it on a FreeBSD.

[dottedmag@…]

Shutdown problem is easily repeated by me under Linux (Debian testing).

I've found Gajim hogs all CPU during shutdown. Moreover strace shows there is no system calls occured during 'stuck' periods. Here is the relevant (I hope) portion of log:

 23:04:30.269960 poll([{fd=7, events=POLLIN}, {fd=3, events=POLLIN}, {fd=5,
 events=POLLIN|POLLPRI|POLLOUT, revents=POLLOUT}, {fd=6,
 events=POLLIN|POLLPRI|POLLOUT, revents=POLLOUT}], 4, 37) = 2
 23:04:30.270088 gettimeofday({1155744270, 270124}, NULL) = 0

 <<< here I press 'quit' button in menu >>>

 23:04:30.270256 send(5, "</stream:stream>", 16, 0) = 16
 23:04:30.270695 write(2, "DEBUG: \33[30;1msocket       sent "..., 61DEBUG:
 socket       sent  </stream:stream>
 ) = 61
 23:04:30.271069 write(2, "DEBUG: \33[36mclient       stop  \33"...,
 62DEBUG: client       stop  Disconnect detected
 ) = 62
 23:04:30.271366 gettimeofday({1155744270, 271406}, NULL) = 0
 23:04:30.271816 stat64("/etc/localtime", {st_mode=S_IFREG|0644,
 st_size=721, ...}) = 0
 23:04:30.272065 write(2, "16 Aug 2006 23:04:30 Gajim: disc"..., 4916 Aug
 2006 23:04:30 Gajim: disconnectedReconnCB
 ) = 49

 <<<here is 6-seconds stop, python2.4 is eating all the CPU>>>

 23:04:36.363296 writev(3,
 [{"l\4\1\1,\0\0\0g\0\0\0p\0\0\0\1\1o\0\34\0\0\0/org/gaj"..., 128},
 {"(\0\0\0\1s\0\0\7\0\0\0offline\0\1s\0\0\17\0\0\0live"..., 44}], 2) = 172
 23:04:36.363700 close(10)               = 0
 23:04:36.363838 close(9)                = 0
 23:04:36.363954 close(11)               = 0
 23:04:36.364046 close(8)                = 0
 23:04:36.364251 write(2, "DEBUG: \33[35mroster       stop  \33"...,
 189DEBUG: roster       stop  Plugging
 <common.xmpp.roster_nb.NonBlockingRoster instance at 0xa6b98c8c> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa6e1440c>.
 ) = 189
 23:04:36.364418 write(2, "DEBUG: \33[0mgen_auth     stop  \33["...,
 187DEBUG: gen_auth     stop  Plugging
 <common.xmpp.auth_nb.NonBlockingNonSASL instance at 0xa6b8346c> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa6e1440c>.
 ) = 187
 23:04:36.364571 write(2, "DEBUG: \33[0msasl         stop  \33["...,
 173DEBUG: sasl         stop  Plugging <common.xmpp.auth_nb.SASL instance
 at 0xa6b8394c> out of <common.xmpp.client_nb.NonBlockingClient instance at
 0xa6e1440c>.
 ) = 173
 23:04:36.364756 write(2, "DEBUG: \33[0mnonblockingt stop  \33["...,
 189DEBUG: nonblockingt stop  Plugging
 <common.xmpp.transports_nb.NonBlockingTLS instance at 0xa6dba06c> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa6e1440c>.
 ) = 189
 23:04:36.364927 write(2, "DEBUG: \33[32mdispatcher   stop  \33"...,
 186DEBUG: dispatcher   stop  Plugging
 <common.xmpp.dispatcher_nb.Dispatcher instance at 0xa6e146ac> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa6e1440c>.
 ) = 186
 23:04:36.365200 write(2, "DEBUG: \33[30;1msocket       stop "...,
 192DEBUG: socket       stop  Plugging
 <common.xmpp.transports_nb.NonBlockingTcp instance at 0xa6e1438c> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa6e1440c>.
 ) = 192
 23:04:36.365327 shutdown(5, 2 /* send and receive */) = 0
 23:04:36.366181 open("/home/mag/.gajim/.config",
 O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 8
 23:04:36.366290 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:36.366614 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:36.366677 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
 MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xa50e1000
 23:04:36.370530 write(8, "last_sounds_dir = \nmsgwin-height"..., 4096) =
 4096
 23:04:36.372644 write(8, "ol = True\nprint_status_in_chats "..., 4096) =
 4096
 23:04:36.376072 write(8,
 "ue\nthemes.\320\274\320\276\321\200\321\201\320\272\320"..., 4096) = 4096
 23:04:36.378113 write(8, "ustom_host = False\naccounts.live"..., 2898) =
 2898
 23:04:36.378168 close(8)                = 0
 23:04:36.378202 munmap(0xa50e1000, 4096) = 0
 23:04:36.378264 stat64("/home/mag/.gajim/config", {st_mode=S_IFREG|0600,
 st_size=15186, ...}) = 0
 23:04:36.378367 unlink("/home/mag/.gajim/config") = 0
 23:04:36.383487 rename("/home/mag/.gajim/.config",
 "/home/mag/.gajim/config") = 0
 23:04:36.383579 chmod("/home/mag/.gajim/config", 0600) = 0
 23:04:36.383745 open("/home/mag/.gajim/.config",
 O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 8
 23:04:36.383807 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:36.383897 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:36.383957 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
 MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xa50e1000
 23:04:36.387787 write(8, "last_sounds_dir = \nmsgwin-height"..., 4096) =
 4096
 23:04:36.389868 write(8, "ol = True\nprint_status_in_chats "..., 4096) =
 4096
 23:04:36.393362 write(8,
 "ue\nthemes.\320\274\320\276\321\200\321\201\320\272\320"..., 4096) = 4096
 23:04:36.395498 write(8, "ustom_host = False\naccounts.live"..., 2898) =
 2898
 23:04:36.395554 close(8)                = 0
 23:04:36.395587 munmap(0xa50e1000, 4096) = 0
 23:04:36.395645 stat64("/home/mag/.gajim/config", {st_mode=S_IFREG|0600,
 st_size=15186, ...}) = 0
 23:04:36.395736 unlink("/home/mag/.gajim/config") = 0
 23:04:36.395828 rename("/home/mag/.gajim/.config",
 "/home/mag/.gajim/config") = 0
 23:04:36.395906 chmod("/home/mag/.gajim/config", 0600) = 0
 23:04:36.396821 gettimeofday({1155744276, 396842}, NULL) = 0

 <<< 5-seconds stop >>>

 23:04:41.978295 writev(3,
 [{"l\4\1\1,\0\0\0h\0\0\0p\0\0\0\1\1o\0\34\0\0\0/org/gaj"..., 128},
 {"(\0\0\0\1s\0\0\7\0\0\0offline\0\1s\0\0\17\0\0\0live"..., 44}], 2) = 172
 23:04:41.978719 write(6, "\27\3\1\0
 \377\240;\310\276q\227\253\307.Mj\302\216\340"..., 90) = 90
 23:04:41.978943 write(2, "DEBUG: \33[30;1msocket       sent "..., 61DEBUG:
 socket       sent  </stream:stream>
 ) = 61
 23:04:41.979134 write(2, "DEBUG: \33[36mclient       stop  \33"...,
 62DEBUG: client       stop  Disconnect detected
 ) = 62
 23:04:41.979284 gettimeofday({1155744281, 979302}, NULL) = 0
 23:04:41.979501 stat64("/etc/localtime", {st_mode=S_IFREG|0644,
 st_size=721, ...}) = 0
 23:04:41.979610 write(2, "16 Aug 2006 23:04:41 Gajim: disc"..., 4916 Aug
 2006 23:04:41 Gajim: disconnectedReconnCB
 ) = 49
 23:04:41.980492 open("/home/mag/.gajim/.config",
 O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 8
 23:04:41.980598 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:41.980751 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:41.980814 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
 MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xa50e1000
 23:04:41.985031 write(8, "last_sounds_dir = \nmsgwin-height"..., 4096) =
 4096
 23:04:41.987257 write(8, "ol = True\nprint_status_in_chats "..., 4096) =
 4096
 23:04:41.990752 write(8,
 "ue\nthemes.\320\274\320\276\321\200\321\201\320\272\320"..., 4096) = 4096
 23:04:41.992861 write(8, "ustom_host = False\naccounts.live"..., 2898) =
 2898
 23:04:41.992918 close(8)                = 0
 23:04:41.992953 munmap(0xa50e1000, 4096) = 0
 23:04:41.993019 stat64("/home/mag/.gajim/config", {st_mode=S_IFREG|0600,
 st_size=15186, ...}) = 0
 23:04:41.993116 unlink("/home/mag/.gajim/config") = 0
 23:04:41.993216 rename("/home/mag/.gajim/.config",
 "/home/mag/.gajim/config") = 0
 23:04:41.993298 chmod("/home/mag/.gajim/config", 0600) = 0
 23:04:41.993456 open("/home/mag/.gajim/.config",
 O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 8
 23:04:41.993515 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:41.993620 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:41.993681 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
 MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xa50e1000
 23:04:42.001640 write(8, "last_sounds_dir = \nmsgwin-height"..., 4096) =
 4096
 23:04:42.006059 write(8, "ol = True\nprint_status_in_chats "..., 4096) =
 4096
 23:04:42.009527 write(8,
 "ue\nthemes.\320\274\320\276\321\200\321\201\320\272\320"..., 4096) = 4096
 23:04:42.011701 write(8, "ustom_host = False\naccounts.live"..., 2898) =
 2898
 23:04:42.011760 close(8)                = 0
 23:04:42.011793 munmap(0xa50e1000, 4096) = 0
 23:04:42.011852 stat64("/home/mag/.gajim/config", {st_mode=S_IFREG|0600,
 st_size=15186, ...}) = 0
 23:04:42.011962 unlink("/home/mag/.gajim/config") = 0
 23:04:42.012061 rename("/home/mag/.gajim/.config",
 "/home/mag/.gajim/config") = 0
 23:04:42.012140 chmod("/home/mag/.gajim/config", 0600) = 0

 <<< Another 5-seconds stop, again eating all CPU >>>

 23:04:47.344475 writev(3,
 [{"l\4\1\0011\0\0\0i\0\0\0p\0\0\0\1\1o\0\34\0\0\0/org/gaj"..., 128},
 {"-\0\0\0\1s\0\0\7\0\0\0offline\0\1s\0\0\24\0\0\0jabb"..., 49}], 2) = 177
 23:04:47.344988 write(2, "DEBUG: \33[35mroster       stop  \33"...,
 189DEBUG: roster       stop  Plugging
 <common.xmpp.roster_nb.NonBlockingRoster instance at 0xa6e37f8c> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa7a2832c>.
 ) = 189
 23:04:47.345155 write(2, "DEBUG: \33[0mbind         stop  \33["...,
 184DEBUG: bind         stop  Plugging <common.xmpp.auth_nb.NonBlockingBind
 instance at 0xa6e14cac> out of <common.xmpp.client_nb.NonBlockingClient
 instance at 0xa7a2832c>.
 ) = 184
 23:04:47.345345 write(2, "DEBUG: \33[0msasl         stop  \33["...,
 173DEBUG: sasl         stop  Plugging <common.xmpp.auth_nb.SASL instance
 at 0xa6e1458c> out of <common.xmpp.client_nb.NonBlockingClient instance at
 0xa7a2832c>.
 ) = 173
 23:04:47.345565 write(2, "DEBUG: \33[0mnonblockingt stop  \33["...,
 189DEBUG: nonblockingt stop  Plugging
 <common.xmpp.transports_nb.NonBlockingTLS instance at 0xa7a282cc> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa7a2832c>.
 ) = 189
 23:04:47.345748 write(2, "DEBUG: \33[32mdispatcher   stop  \33"...,
 186DEBUG: dispatcher   stop  Plugging
 <common.xmpp.dispatcher_nb.Dispatcher instance at 0xa6e14b8c> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa7a2832c>.
 ) = 186
 23:04:47.346074 write(2, "DEBUG: \33[30;1msocket       stop "...,
 192DEBUG: socket       stop  Plugging
 <common.xmpp.transports_nb.NonBlockingTcp instance at 0xa6e141ec> out of
 <common.xmpp.client_nb.NonBlockingClient instance at 0xa7a2832c>.
 ) = 192
 23:04:47.346208 shutdown(6, 2 /* send and receive */) = 0

 <<< Another 5-seconds stop >>>

 23:04:52.594859 writev(3,
 [{"l\4\1\0011\0\0\0j\0\0\0p\0\0\0\1\1o\0\34\0\0\0/org/gaj"..., 128},
 {"-\0\0\0\1s\0\0\7\0\0\0offline\0\1s\0\0\24\0\0\0jabb"..., 49}], 2) = 177
 23:04:52.595222 write(7, "+\7\1\0", 4)  = 4
 23:04:52.595310 read(7, "\6\0\241|\323\7\272\27L\0\0\0\"\0
 \1\0\0\0\0+\0E\2)\0\230"..., 32) = 32

 <<<many read(2)s skipped>>>

 23:04:52.605672 read(7,
 "\1\1\242|\0\0\0\0\4\0\0\1\4\0\0\0(\0\0\0\4\0\0\0\\-\34"..., 32) = 32
 23:04:52.605862 stat64("/home/mag/.gajim/gajim.pid",
 {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:04:52.605969 unlink("/home/mag/.gajim/gajim.pid") = 0
 23:04:52.606350 rt_sigaction(SIGINT, {SIG_DFL}, {0x80e4ca0, [], 0}, 8) = 0
 23:04:52.644632 gettimeofday({1155744292, 644751}, NULL) = 0
 23:04:52.651982 close(4)                = 0
 23:04:52.671482 munmap(0xa7fe8000, 4096) = 0
 23:04:52.671644 exit_group(0)           = ?

[dottedmag@…]

I also found the place where gajim is stuck during startup - between

reading vcards and logs:

 23:17:16.481954 stat64("/home/mag/.gajim/vcards/fox@jabber.volgo-
 balt.ru-", {st_mode=S_IFREG|0644, st_size=321, ...}) = 0
 23:17:16.482227 stat64("/home/mag/.gajim/vcards/fox@jabber.volgo-
 balt.ru-", {st_mode=S_IFREG|0644, st_size=321, ...}) = 0
 23:17:16.482354 open("/home/mag/.gajim/vcards/fox@jabber.volgo-balt.ru-",
 O_RDONLY|O_LARGEFILE) = 8
 23:17:16.482426 fstat64(8, {st_mode=S_IFREG|0644, st_size=321, ...}) = 0
 23:17:16.482503 fstat64(8, {st_mode=S_IFREG|0644, st_size=321, ...}) = 0
 23:17:16.482577 _llseek(8, 0, [0], SEEK_CUR) = 0
 23:17:16.482628 fstat64(8, {st_mode=S_IFREG|0644, st_size=321, ...}) = 0
 23:17:16.482703 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
 MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xa7fe7000
 23:17:16.482761 _llseek(8, 0, [0], SEEK_CUR) = 0
 23:17:16.482831 read(8, "<vCard xmlns=\"vcard-temp\"><TITLE"..., 4096) =
 321
 23:17:16.482897 read(8, "", 4096)       = 0
 23:17:16.482964 close(8)                = 0
 23:17:16.483013 munmap(0xa7fe7000, 4096) = 0
 23:17:16.484829
 stat64("/home/mag/.gajim/vcards/30667711@icq.jabber.dottedmag.net-",
 {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:17:16.485075
 stat64("/home/mag/.gajim/vcards/30667711@icq.jabber.dottedmag.net-",
 {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:17:16.485202
 open("/home/mag/.gajim/vcards/30667711@icq.jabber.dottedmag.net-",
 O_RDONLY|O_LARGEFILE) = 8
 23:17:16.485274 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:17:16.485350 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:17:16.485424 _llseek(8, 0, [0], SEEK_CUR) = 0
 23:17:16.485475 fstat64(8, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
 23:17:16.485549 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
 MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xa7fe7000
 23:17:16.485624 _llseek(8, 0, [0], SEEK_CUR) = 0
 23:17:16.485696 read(8, "", 8192)       = 0
 23:17:16.485765 close(8)                = 0
 23:17:16.485812 munmap(0xa7fe7000, 4096) = 0

 <<< 2.5-seconds stuck, no I/O or CPU consumption >>>

 23:17:19.023661 fcntl64(4, F_SETLK64, {type=F_RDLCK, whence=SEEK_SET,
 start=1073741824, len=1}, 0xafffce74) = 0
 23:17:19.023858 fcntl64(4, F_SETLK64, {type=F_RDLCK, whence=SEEK_SET,
 start=1073741826, len=510}, 0xafffce74) = 0
 23:17:19.023919 fcntl64(4, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET,
 start=1073741824, len=1}, 0xafffce74) = 0
 23:17:19.023982 access("/home/mag/.gajim/logs.db-journal", F_OK) = -1
 ENOENT (No such file or directory)
 23:17:19.024055 fstat64(4, {st_mode=S_IFREG|0600, st_size=2228224, ...}) =
 0
 23:17:19.024140 _llseek(4, 0, [0], SEEK_SET) = 0
 23:17:19.024192 read(4, "SQLite format 3\0\4\0\1\1\0@
 \0\0\324\271\0\0\0\0"..., 1024) = 1024
 23:17:19.024276 _llseek(4, 3072, [3072], SEEK_SET) = 0
 23:17:19.024328 read(4,
 "\2\0\0\0\1\3\332\0\0\0\5\305\3\332\0\0\0\0\0\0\0\0\0\0"..., 1024) = 1024
 23:17:19.024414 _llseek(4, 1510400, [1510400], SEEK_SET) = 0
 23:17:19.024466 read(4,
 "\2\0\0\0\f\2\20\0\0\0\0\34\2\20\2;\2f\2\222\2\276\2\352"..., 1024) = 1024
 23:17:19.024541 _llseek(4, 14336, [14336], SEEK_SET) = 0
 23:17:19.024592 read(4,
 "\n\0\0\0\27\0\313\0\0\313\0\350\1\20\1-\1U\1|\1\244\1\313"..., 1024) =
 1024
 23:17:19.024757 fcntl64(4, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET,
 start=0, len=0}, 0xafffcf34) = 0
 23:17:19.024939 fcntl64(4, F_SETLK64, {type=F_RDLCK, whence=SEEK_SET,
 start=1073741824, len=1}, 0xafffd084) = 0
 23:17:19.025002 fcntl64(4, F_SETLK64, {type=F_RDLCK, whence=SEEK_SET,
 start=1073741826, len=510}, 0xafffd084) = 0
 23:17:19.025060 fcntl64(4, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET,
 start=1073741824, len=1}, 0xafffd084) = 0
 23:17:19.025118 access("/home/mag/.gajim/logs.db-journal", F_OK) = -1
 ENOENT (No such file or directory)
 23:17:19.025181 fstat64(4, {st_mode=S_IFREG|0600, st_size=2228224, ...}) =
 0