"File Open" dialogues for gedit, etc., take 25 seconds to appear

Binary package hint: tracker

Ubuntu 9.04, tracker 0.6.93-0ubuntu1. trackerd and tracker-indexer
reached deadlock over a couple of ~/.cache/tracker files resulting in 25
second timeouts before the "File Open" dialogue of various programs
would appear.

A friend reported the "File Open" dialogues of various GUI programs,
e.g. gedit, Scite, ooffice, was very slow in opening, e.g. taking more
than 20 seconds. I strace'd gedit whilst he did a "File Open".

    15520 22.5956 gettimeofday({1242636766, 167011}, NULL) = 0
    15520 22.5963 writev(15, [{"l\1\0\1\34\0\0\0\r\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/free"..., 144}, {"\27\0\0\0org.freedesktop.Tracker\0"..., 28}], 2) = 172
    15520 22.5966 gettimeofday({1242636766, 167998}, NULL) = 0
    15520 22.5967 writev(15, [{"l\1\0\1\0\0\0\0\16\0\0\0{\0\0\0\1\1o\0\30\0\0\0/org/free"..., 144}, {""..., 0}], 2) = 144
    15520 22.5968 gettimeofday({1242636766, 168246}, NULL) = 0
    15520 22.5976 poll([{fd=15, events=POLLIN}], 1, 25000) = 1 ([{fd=15, revents=POLLIN}])
    15520 22.5977 read(15, "l\2\1\1\0\0\0\0\3\0\0\0005\0\0\0\6\1s\0\6\0\0\0:1.160\0\0\5"..., 2048) = 882
    15520 22.5981 read(15, 0xf82e20, 2048) = -1 EAGAIN (Resource temporarily unavailable)
    15520 22.5982 gettimeofday({1242636766, 169625}, NULL) = 0
    15520 22.5983 poll([{fd=15, events=POLLIN}], 1, 24999) = 0 (Timeout)
    15520 47.6211 gettimeofday({1242636791, 192561}, NULL) = 0
    15520 47.6215 writev(15, [{"l\1\1\1w\0\0\0\17\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/free"..., 144}, {"r\0\0\0type='signal',sender='org.fre"..., 119}], 2) = 263
    15520 47.6219 writev(15, [{"l\1\1\1\211\0\0\0\20\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/free"..., 144}, {"\204\0\0\0type='signal',sender='org.fre"..., 137}], 2) = 281
    15520 47.6221 writev(15, [{"l\1\1\1\211\0\0\0\21\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/free"..., 144}, {"\204\0\0\0type='signal',sender='org.fre"..., 137}], 2) = 281

Note the 25.0228 second gap between the start of the poll() and the next
system call; this matches the 25 second delay the user sees. gedit's
file descriptor 15 is a socket.

    $ lsof -p 15520
    gedit 15520 peter 15u unix 0xffff88005317ec00 2003719 socket

After a bit of poking around, I realised it was trying to read from
trackerd.

    $ ps l $(pidof trackerd) $(pidof tracker-indexer)
    F UID PID PPID PRI NI VSZ RSS WCHAN STAT TTY TIME COMMAND
    0 1000 5339 5196 39 19 310584 10184 hrtime SN ? 0:58 /usr/lib/tracker/trackerd
    0 1000 5370 1 39 19 175772 18392 hrtime SNl ? 1:02 /usr/lib/tracker/tracker-indexer
    $

strace showed trackerd was endlessly attempting to get a read lock on
its FD 12.

    $ strace -tt -p 5339
    10:16:42.095702 fcntl(12, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
    10:16:42.096032 nanosleep({0, 100000000}, NULL) = 0
    10:16:42.196494 fcntl(12, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}) = -1 EAGAIN (Resource temporarily unavailable)
    10:16:42.196816 nanosleep({0, 100000000}, NULL) = 0

trackerd's FD 12 is file-meta.db.

    $ lsof -p 5339
    trackerd 5339 peter 12u REG 8,52 2077696 17186898 /home/peter/.cache/tracker/file-meta.db

And one other program, tracker-indexer, has that file open.

    $ lsof /home/peter/.cache/tracker/file-meta.db
    COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
    trackerd 5339 peter 12u REG 8,52 2077696 17186898 /home/peter/.cache/tracker/file-meta.db
    tracker-i 5370 peter 15uw REG 8,52 2077696 17186898 /home/peter/.cache/tracker/file-meta.db
    $

It's endlessly trying to get a write lock on its FD 13,

    $ strace -tt -p 5370
    10:18:46.653514 fcntl(13, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741826, len=510}) = -1 EAGAIN (Resource temporarily unavailable)
    10:18:46.653655 nanosleep({0, 100000000}, NULL) = 0
    10:18:46.753864 fcntl(13, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=1073741826, len=510}) = -1 EAGAIN (Resource temporarily unavailable)
    10:18:46.754004 nanosleep({0, 100000000}, NULL) = 0

which is common.db,

    $ lsof -p 5370
    tracker-i 5370 peter 13ur REG 8,52 84992 17186897 /home/peter/.local/share/tracker/data/common.db

and trackerd is the other program that has that file open.

    $ lsof /home/peter/.local/share/tracker/data/common.db
    COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
    trackerd 5339 peter 10ur REG 8,52 84992 17186897 /home/peter/.local/share/tracker/data/common.db
    tracker-i 5370 peter 13ur REG 8,52 84992 17186897 /home/peter/.local/share/tracker/data/common.db
    $

The inode numbers of the two files,

    $ ls -i /home/peter/.cache/tracker/file-meta.db \
    > /home/peter/.local/share/tracker/data/common.db
    17186898 /home/peter/.cache/tracker/file-meta.db
    17186897 /home/peter/.local/share/tracker/data/common.db

which appear in the list of all the locks held.

    $ cat /proc/locks
    1: POSIX ADVISORY READ 8029 08:34:17187002 1073741826 1073742335
    2: POSIX ADVISORY READ 15938 08:32:2810628 0 EOF
    3: POSIX ADVISORY READ 15938 08:32:2771634 0 EOF
    4: POSIX ADVISORY READ 15938 08:32:2771633 0 EOF
    5: POSIX ADVISORY READ 15938 08:32:2810417 0 EOF
    6: POSIX ADVISORY READ 15938 08:32:2810616 0 EOF
    7: POSIX ADVISORY READ 15938 08:32:2810627 0 EOF
    8: POSIX ADVISORY READ 15938 08:32:2810416 0 EOF
    9: POSIX ADVISORY WRITE 8029 08:34:17186986 1073741824 1073742335
    10: POSIX ADVISORY WRITE 8029 08:34:17186981 0 EOF
    11: POSIX ADVISORY READ 5339 08:34:17186897 1073741826 1073742335
    12: POSIX ADVISORY WRITE 5370 08:34:17186897 1073741824 1073741825
    13: POSIX ADVISORY WRITE 5370 08:34:17186899 1073741824 1073742335
    14: POSIX ADVISORY WRITE 5370 08:34:17186898 1073741824 1073742335
    15: POSIX ADVISORY READ 5370 08:34:17186897 1073741826 1073742335
    16: FLOCK ADVISORY WRITE 4885 00:12:10848 0 EOF
    17: POSIX ADVISORY WRITE 4858 00:12:10817 0 EOF
    $

Re-ording that a bit and adding in the lock attempts from above, we have

    common.db 1073741824 len=2 WRITE tracker-indexer
    common.db 1073741826 len=510 READ trackerd
    common.db 1073741826 len=510 READ tracker-indexer
    common.db 1073741826 len=510 F_WRLCK tracker-indexer

    file-meta.db 1073741824 len=512 WRITE tracker-indexer
    file-meta.db 1073741824 len=1 F_RDLCK trackerd

It's clear that both are trying to get a lock that's blocked by an
existing lock the other has on the same file. This bug could be
confirmed based solely on the above investigation IMHO, it does not need
someone else to suffer the same bug *and* get to the point where they
realise it's the above causing it. This thread,
http://ubuntuforums.org/showthread.php?t=811795, has users suffering
similar problems. Their solution is to purge the tracker package!