GNOME Bugzilla – Bug 568332
stuck in a loop updating folders.db
Last modified: 2009-09-22 01:22:32 UTC
Steps to reproduce: Not sure. Stack trace:
+ Trace 211681
Thread 1 (Thread 0xb62ba940 (LWP 27243))
Thread 1 (Thread 0xb63a6940 (LWP 15974))
Other information: evolution seems to be in a loop, continually updating the folders.db file in an imap account. See the following strace excerpt. This happens over and over again. Probably the lseek offsets are different each time through though. However while this is all happening, the UI is completely unresponsive and does not react to expose events (i.e. does not repaint). ... [pid 19499] gettimeofday({1232392892, 231337}, NULL) = 0 [pid 19499] gettimeofday({1232392892, 268685}, NULL) = 0 [pid 19499] fcntl64(40, F_SETLK64, {type=F_RDLCK, whence=SEEK_SET, start=1073741824, len=1}, 0xb29fea04) = 0 [pid 19499] fcntl64(40, F_SETLK64, {type=F_RDLCK, whence=SEEK_SET, start=1073741826, len=510}, 0xb29fea04) = 0 [pid 19499] fcntl64(40, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET, start=1073741824, len=1}, 0xb29fea04) = 0 [pid 19499] access("/home/brian/.evolution/mail/imap/brian@mail/folders.db-journal", F_OK) = -1 ENOENT (No such file or directory) [pid 19499] fstat64(40, {st_mode=S_IFREG|0644, st_size=267448320, ...}) = 0 [pid 19499] _llseek(40, 24, [24], SEEK_SET) = 0 [pid 19499] read(40, "\0\3[x\0\0\0\0\0\0\203Z\0\0\rx", 16) = 16 [pid 19499] fcntl64(40, F_SETLK64, {type=F_WRLCK, whence=SEEK_SET, start=1073741825, len=1}, 0xb29feaa4) = 0 [pid 19499] open("/home/brian/.evolution/mail/imap/brian@mail/folders.db-journal", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE|O_NOFOLLOW, 0644) = 31 [pid 19499] open("/home/brian/.evolution/mail/imap/brian@mail", O_RDONLY|O_LARGEFILE) = 32 [pid 19499] fcntl64(32, F_GETFD) = 0 [pid 19499] fcntl64(32, F_SETFD, FD_CLOEXEC) = 0 [pid 19499] fcntl64(31, F_GETFD) = 0 [pid 19499] fcntl64(31, F_SETFD, FD_CLOEXEC) = 0 [pid 19499] fstat64(31, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 [pid 19499] _llseek(31, 0, [0], SEEK_SET) = 0 [pid 19499] write(31, "\331\325\5\371 \241c\327\0\0\0\0\273\332\212u\0\3\374<"..., 512) = 512 [pid 19499] _llseek(31, 512, [512], SEEK_SET) = 0 [pid 19499] write(31, "\0\2\202\304", 4) = 4 [pid 19499] _llseek(31, 516, [516], SEEK_SET) = 0 [pid 19499] write(31, "\2\0\0\0\26\1\356\0\0\2*\245\0029\2Q\2i\2\201\2\231\2\261"..., 1024) = 1024 [pid 19499] _llseek(31, 1540, [1540], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\212\334", 4) = 4 [pid 19499] _llseek(31, 1544, [1544], SEEK_SET) = 0 [pid 19499] write(31, "\0\3\227n", 4) = 4 [pid 19499] _llseek(31, 1548, [1548], SEEK_SET) = 0 [pid 19499] write(31, "\n\0\0\0.\0f\0\0\272\0\317\0\344\0\371\1\16\1#\0018\1M"..., 1024) = 1024 [pid 19499] _llseek(31, 2572, [2572], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\213\220", 4) = 4 [pid 19499] _llseek(31, 2576, [2576], SEEK_SET) = 0 [pid 19499] write(31, "\0\3\204\214", 4) = 4 [pid 19499] _llseek(31, 2580, [2580], SEEK_SET) = 0 [pid 19499] write(31, "\n\0\0\0*\0\216\0\0\216\0\243\0\270\0\315\0\342\0\367\1"..., 1024) = 1024 [pid 19499] _llseek(31, 3604, [3604], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\213\326", 4) = 4 [pid 19499] _llseek(31, 3608, [3608], SEEK_SET) = 0 [pid 19499] write(31, "\0\3\237\267", 4) = 4 [pid 19499] _llseek(31, 3612, [3612], SEEK_SET) = 0 [pid 19499] write(31, "\n\0\0\0)\0\365\0\0\365\1\10\1\33\1.\1A\1T\1g\1z\1\215"..., 1024) = 1024 [pid 19499] _llseek(31, 4636, [4636], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\213S", 4) = 4 [pid 19499] _llseek(31, 4640, [4640], SEEK_SET) = 0 [pid 19499] write(31, "\0\2\204\f", 4) = 4 [pid 19499] _llseek(31, 4644, [4644], SEEK_SET) = 0 [pid 19499] write(31, "\2\0\0\0\26\1\356\0\0\2*\246\0029\2Q\2i\2\201\2\231\2\261"..., 1024) = 1024 [pid 19499] _llseek(31, 5668, [5668], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\212\334", 4) = 4 [pid 19499] _llseek(31, 5672, [5672], SEEK_SET) = 0 [pid 19499] write(31, "\0\3\327\362", 4) = 4 [pid 19499] _llseek(31, 5676, [5676], SEEK_SET) = 0 [pid 19499] write(31, "\n\0\0\0.\0f\0\0\272\0\317\0\344\0\371\1\16\1#\0018\1M"..., 1024) = 1024 [pid 19499] _llseek(31, 6700, [6700], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\213\220", 4) = 4 [pid 19499] _llseek(31, 6704, [6704], SEEK_SET) = 0 [pid 19499] write(31, "\0\3\326\312", 4) = 4 [pid 19499] _llseek(31, 6708, [6708], SEEK_SET) = 0 [pid 19499] write(31, "\n\0\0\0*\0\216\0\0\216\0\243\0\270\0\315\0\342\0\367\1"..., 1024) = 1024 [pid 19499] _llseek(31, 7732, [7732], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\213\326", 4) = 4 [pid 19499] _llseek(31, 7736, [7736], SEEK_SET) = 0 [pid 19499] write(31, "\0\3\336x", 4) = 4 [pid 19499] _llseek(31, 7740, [7740], SEEK_SET) = 0 [pid 19499] write(31, "\n\0\0\0)\0\365\0\0\365\1\10\1\33\1.\1A\1T\1g\1z\1\215"..., 1024) = 1024 [pid 19499] _llseek(31, 8764, [8764], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\213S", 4) = 4 [pid 19499] _llseek(31, 8768, [8768], SEEK_SET) = 0 [pid 19499] write(31, "\0\0cF", 4) = 4 [pid 19499] _llseek(31, 8772, [8772], SEEK_SET) = 0 [pid 19499] write(31, "\r\0\0\0-\0|\0\3\354\3\330\3\304\3\260\3\234\3\210\3t\3"..., 1024) = 1024 [pid 19499] _llseek(31, 9796, [9796], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\212\270", 4) = 4 [pid 19499] _llseek(31, 9800, [9800], SEEK_SET) = 0 [pid 19499] write(31, "\0\0\0\1", 4) = 4 [pid 19499] _llseek(31, 9804, [9804], SEEK_SET) = 0 [pid 19499] write(31, "SQLite format 3\0\4\0\1\1\0@ \0\3[x\0\0\0\0"..., 1024) = 1024 [pid 19499] _llseek(31, 10828, [10828], SEEK_SET) = 0 [pid 19499] write(31, "\273\332\212u", 4) = 4 [pid 19499] fsync(31) = 0 [pid 19499] fsync(32) = 0 [pid 19499] close(32) = 0 [pid 19499] _llseek(31, 8, [8], SEEK_SET) = 0 [pid 19499] write(31, "\0\0\0\n", 4) = 4 [pid 19499] fsync(31) = 0 [pid 19499] fcntl64(40, F_SETLK64, {type=F_WRLCK, whence=SEEK_SET, start=1073741824, len=1}, 0xb29fe904) = 0 [pid 19499] fcntl64(40, F_SETLK64, {type=F_WRLCK, whence=SEEK_SET, start=1073741826, len=510}, 0xb29fe904) = 0 [pid 19499] _llseek(40, 0, [0], SEEK_SET) = 0 [pid 19499] write(40, "SQLite format 3\0\4\0\1\1\0@ \0\3[y\0\0\0\0"..., 1024) = 1024 [pid 19499] _llseek(40, 26022912, [26022912], SEEK_SET) = 0 [pid 19499] write(40, "\r\0\0\0.\0h\0\3\354\3\330\3\304\3\260\3\234\3\210\3t\3"..., 1024) = 1024 [pid 19499] _llseek(40, 168496128, [168496128], SEEK_SET) = 0 [pid 19499] write(40, "\2\0\0\0\26\1\356\0\0\2*\245\0029\2Q\2i\2\201\2\231\2\261"..., 1024) = 1024 [pid 19499] _llseek(40, 168832000, [168832000], SEEK_SET) = 0 [pid 19499] write(40, "\2\0\0\0\26\1\356\0\0\2*\246\0029\2Q\2i\2\201\2\231\2\261"..., 1024) = 1024 [pid 19499] _llseek(40, 236071936, [236071936], SEEK_SET) = 0 [pid 19499] write(40, "\n\0\0\0+\0y\0\0y\0\216\0\243\0\270\0\315\0\342\0\367\1"..., 1024) = 1024 [pid 19499] _llseek(40, 241021952, [241021952], SEEK_SET) = 0 [pid 19499] write(40, "\n\0\0\0+\0\237\0\0\237\0\264\0\311\0\336\0\363\1\10\1"..., 1024) = 1024 [pid 19499] _llseek(40, 243193856, [243193856], SEEK_SET) = 0 [pid 19499] write(40, "\n\0\0\0,\0\274\0\0\274\0\317\0\342\0\365\1\10\1\33\1."..., 1024) = 1024 [pid 19499] _llseek(40, 257631232, [257631232], SEEK_SET) = 0 [pid 19499] write(40, "\n\0\0\0+\0y\0\0y\0\216\0\243\0\270\0\315\0\342\0\367\1"..., 1024) = 1024 [pid 19499] _llseek(40, 257934336, [257934336], SEEK_SET) = 0 [pid 19499] write(40, "\n\0\0\0+\0\237\0\0\237\0\264\0\311\0\336\0\363\1\10\1"..., 1024) = 1024 [pid 19499] _llseek(40, 259644416, [259644416], SEEK_SET) = 0 [pid 19499] write(40, "\n\0\0\0,\0\274\0\0\274\0\317\0\342\0\365\1\10\1\33\1."..., 1024) = 1024 [pid 19499] fsync(40) = 0 [pid 19499] close(31) = 0 [pid 19499] unlink("/home/brian/.evolution/mail/imap/brian@mail/folders.db-journal") = 0 [pid 19499] fcntl64(40, F_SETLK64, {type=F_RDLCK, whence=SEEK_SET, start=1073741826, len=510}, 0xb29fea84) = 0 [pid 19499] fcntl64(40, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET, start=1073741824, len=2}, 0xb29fea84) = 0 [pid 19499] fcntl64(40, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}, 0xb29fea64) = 0 [pid 19499] gettimeofday({1232392892, 406435}, NULL) = 0 [pid 19499] gettimeofday({1232392892, 469793}, NULL) = 0 [pid 19499] brk(0xffc9000) = 0xffc9000 [pid 19499] brk(0x10009000) = 0x10009000 [pid 19499] gettimeofday({1232392892, 675978}, NULL) = 0 [pid 19499] gettimeofday({1232392892, 676142}, NULL) = 0 [pid 19499] gettimeofday({1232392892, 676272}, NULL) = 0 [pid 19499] gettimeofday({1232392892, 676398}, NULL) = 0
And here it goes again. While this is happening, I see the following in my .evolution/mail/imap/brian@mail/ dir: $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265316 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 3856 -rw-r--r-- 1 brian brian 3941056 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265320 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 3860 -rw-r--r-- 1 brian brian 3944984 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265396 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 3936 -rw-r--r-- 1 brian brian 4022384 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265464 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4004 -rw-r--r-- 1 brian brian 4095656 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265464 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4004 -rw-r--r-- 1 brian brian 4095656 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265520 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4060 -rw-r--r-- 1 brian brian 4153272 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265620 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4160 -rw-r--r-- 1 brian brian 4247184 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265628 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4168 -rw-r--r-- 1 brian brian 4252344 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265628 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4168 -rw-r--r-- 1 brian brian 4252344 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265656 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4196 -rw-r--r-- 1 brian brian 4283112 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265740 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4280 -rw-r--r-- 1 brian brian 4368768 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265776 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4316 -rw-r--r-- 1 brian brian 4406952 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ total 265788 4 drwx------ 105 brian brian 4096 2008-11-30 10:32 folders 4 drwxr-xr-x 11 brian brian 4096 2008-11-30 10:54 .. 4 -rw------- 1 brian brian 3729 2009-01-19 17:25 .ev-store-summary 4 drwxr-xr-x 2 brian brian 4096 2009-01-19 17:26 system 4 drwx------ 4 brian brian 4096 2009-01-19 17:26 . 4328 -rw-r--r-- 1 brian brian 4417096 2009-01-19 17:27 folders.db-journal 261440 -rw-r--r-- 1 brian brian 267448320 2009-01-19 17:27 folders.db $ ls -sltar /home/brian/.evolution/mail/imap/brian@mail/ Obviously it's doing massive updates to the folders.db database but while it does it, the UI is completely dead. I thought this new SQLite database scheme was supposed to make things faster/better, not make my evolution go AWOL for hours at a time updating databases.
*** Bug 568297 has been marked as a duplicate of this bug. ***
Fairly the fsync/sqlite3/ext3 issue. This must be solved like what FF did by writing a async io/fsync thread.
Milan, keep your sqlite-vfs patches here. I would like to push them for tomorrow's release. Thanks.
Created attachment 127442 [details] [review] proposed eds patch for evolution-data-server;
Milan commit to stable/trunk. Yeah, Im brave to say so ;-) also I'm confident. I see that this brings in 75% performance improvement. FF does teh same. Lets see if we get back any regressions, I hope not, given that I have been using it for a week almost.
Committed to trunk. Committed revision 9993. Committed to gnome-2-24. Committed revision 9994. ...cross fingers...
*** Bug 557361 has been marked as a duplicate of this bug. ***
So it looks like the patch here leaks threads, causing Evolution to eventually stop displaying messages. Reports of this are already starting to trickle in, such as http://bugzilla.redhat.com/show_bug.cgi?id=489696. Milan was kind enough to guide me through the logic yesterday, and I rewrote part of it with a simpler thread design and no leaks. Reopening and marking as BLOCKER. This might warrant a code freeze break so we don't ship a broken 2.26 right out of the gate.
Created attachment 130466 [details] [review] Revised patch This spawns a single thread per database file, which just processes sync requests as they arrive on a queue. The rest of the code rate limits the requests. Shouldn't be any leaks here.
*** Bug 575229 has been marked as a duplicate of this bug. ***
Is it in Matt?
Yeah, sorry. Revision 10162. Closing bug.
The revised patch applies to evolution-data-server 2.24.5 and seems to fix the problems I described in bug 575229. Thanks!
*** Bug 575996 has been marked as a duplicate of this bug. ***
*** Bug 578413 has been marked as a duplicate of this bug. ***
*** Bug 569187 has been marked as a duplicate of this bug. ***
bug 580820 looks dupe but it has been filed against 2.26.1 :/
*** Bug 545898 has been marked as a duplicate of this bug. ***
*** Bug 572548 has been marked as a duplicate of this bug. ***
*** Bug 562559 has been marked as a duplicate of this bug. ***
*** Bug 595878 has been marked as a duplicate of this bug. ***