Bug 319157

Summary: Excessive I/O usage during mail import with KMailCVT.
Product: [Frameworks and Libraries] Akonadi Reporter: Martin Steigerwald <Martin>
Component: Maildir ResourceAssignee: kdepim bugs <kdepim-bugs>
Status: RESOLVED UNMAINTAINED    
Severity: grave    
Priority: NOR    
Version: 4.10   
Target Milestone: ---   
Platform: Debian unstable   
OS: Linux   
Latest Commit: Version Fixed In:
Sentry Crash Report:
Attachments: atopsar output during the time of high disk I/O usage
atop log file which can be used together with atopsar
screenshot of atop with statistic since boot
typical 10 seconds snapshot of atop with maildir agent doing lots of I/O

Description Martin Steigerwald 2013-05-01 10:24:01 UTC
I am setting this to grave as this behaviour may destroy SSDs.

It appears to me that bug #315947 is not yet fixed. But my issue might be something different as well, cause I am seeing this behaviour after having run KMailCVT.

I am currently on my second try to migrate from KDEPIM 4.4.11 to KDEPIM 4.10.2 on my Debian Sid installation. This time I use the recommended approach to start from scratch and import my mails:

martin@merkaba:~/Backup> du -sh Mail-Alt
6,7G    Mail-Alt
martin@merkaba:~/Backup> find Mail-Alt -type f | wc -l
447779
martin@merkaba:~/Backup> find Mail-Alt -type d | wc -l
840
martin@merkaba:~/Backup>

atop reports my that the maildir agent already used up 368,7 GB.

This is 61x times the amount of space of the KMail-1 mixded maildir I imported. I made sure that there are no mbox files in it.

Reproducible: Didn't try

Steps to Reproduce:
1. Do a KDEPIM-2 setup from scratch
2. Disable mail indexing
3. Don´t run the migrator
4. Use KMailCVT to import old mails (without deleting duplicates)
Actual Results:  
KMailCVT completes pretty fast, but KMail-2 keeps unresponsive and I see this since about an hour already:

martin@merkaba:~/Backup> vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 2  2  18496 1492104  88412 2737616    1    2   880  1551  113   54 17  2 79  1
 2  0  18496 1442568  88412 2787688    0    0    80 69088 3805 16017 43  8 44  6
 2  1  18496 1439100  88420 2790100    0    0    76 103680 3233 13271 36  7 46 10
 2  0  18496 1475372  88420 2755028    0    0   132 69096 3257 14271 33  7 47 13
 1  1  18496 1482848  88420 2746472    0    0   112 103788 3407 15593 36  7 46 12
 1  1  18496 1468900  88420 2760732    0    0    88 105392 3510 14642 39  7 44 10
 2  0  18496 1444772  88420 2784908    0    0    16 69112 3956 19002 41 11 38 10
 3  0  18496 1430400  88428 2799604    0    0    76 69164 3439 14195 39  9 45  8
 0  2  18496 1479756  88428 2750136    0    0    40 103680 3582 14124 32  8 45 15
 4  0  18496 1477912  88428 2751936    0    0   356 69128 2980 12293 37  6 50  7
 1  1  18496 1483032  88428 2745756    0    0   100 103700 3444 13683 34 10 44 12
 3  1  18496 1498952  88428 2729880    0    0    60 69140 3278 12623 37  8 47  9
 2  0  18496 1480140  88436 2749428    0    0    56 69192 3401 13724 39  7 46  8
 0  2  18496 1493036  88436 2735732    0    0    80 103732 3264 14039 36  7 47 10
 2  0  18496 1485352  88436 2744328    0    0    72 69160 3240 13224 36  7 49  9
 1  1  18496 1486988  88436 2741568    0    0   108 103884 3575 16732 38  7 44 11
 1  1  18496 1495584  88436 2733020    0    0    72 69168 3479 14323 38  7 47  8
 2  0  18496 1479380  88444 2750100    0    0    84 69224 3363 14393 39  7 46  7
 0  2  18496 1437836  88444 2790768    0    0    88 103776 3643 15913 38 11 41 11

martin@merkaba:/home2/martin#130> date; while true; do ls -lh Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat ; sleep 1 ; done 
Mi 1. Mai 12:19:55 CEST 2013
-rw-r--r-- 1 martin martin 13M Mai  1 12:19 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 26M Mai  1 12:19 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 30M Mai  1 12:19 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 1,6M Mai  1 12:19 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 25M Mai  1 12:19 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 0 Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 12M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 23M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 8,9M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 35M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 0 Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 22M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 32M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 29M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 0 Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 8,8M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 30M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 0 Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 25M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 0 Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 17M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 32M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 0 Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 15M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 0 Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 5,7M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 13M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
-rw-r--r-- 1 martin martin 33M Mai  1 12:20 Akonadi/Konfiguration/agent_config_akonadi_maildir_resource_0_changes.dat
^C% 

ATOP - merkaba            2013/05/01  12:20:38            ---------            1d20h57m16s elapsed
PRC | sys   66m30s |  user   2h51m | #proc    273 |  #tslpu     0 | #zombie    0 |  #exit      0 |
CPU | sys       9% |  user     70% | irq       0% |  idle    314% | wait      6% |  curscal   ?% |
cpu | sys       2% |  user     34% | irq       0% |  idle     62% | cpu002 w  1% |  curscal   ?% |
cpu | sys       2% |  user     22% | irq       0% |  idle     75% | cpu003 w  1% |  curscal   ?% |
cpu | sys       2% |  user      7% | irq       0% |  idle     89% | cpu000 w  2% |  curscal   ?% |
cpu | sys       2% |  user      7% | irq       0% |  idle     89% | cpu001 w  2% |  curscal   ?% |
CPL | avg1    2.31 |  avg5    2.38 | avg15   2.55 |  csw 407966e3 | intr 11969e4 |  numcpu     4 |
MEM | tot     7.6G |  free    1.3G | cache   2.7G |  buff   86.9M | slab    1.2G |  shmem 250.7M |
SWP | tot    12.0G |  free   12.0G |              |               | vmcom   3.7G |  vmlim  15.8G |
PAG | scan 15480e3 |  steal 1507e4 | stall   5092 |               | swin   51794 |  swout 145699 |
LVM | erkaba-home2 |  busy      3% | read   44961 |  write 1995e3 | MBw/s   2.87 |  avio 1.04 ms |
LVM | merkaba-home |  busy      3% | read 2709212 |  write 425612 | MBw/s   0.19 |  avio 0.65 ms |
LVM | rkaba-debian |  busy      1% | read  666090 |  write 670366 | MBw/s   0.17 |  avio 0.33 ms |
LVM | merkaba-swap |  busy      0% | read   52118 |  write 145701 | MBw/s   0.00 |  avio 0.06 ms |
DSK |          sda |  busy      5% | read 1951569 |  write 1968e3 | MBw/s   3.23 |  avio 0.90 ms |
NET | transport    |  tcpi  693664 | tcpo  497845 |  udpi   68906 | udpo   41345 |  tcpao   5246 |
NET | network      |  ipi   880745 | ipo   539020 |  ipfrw      0 | deliv 879128 |  icmpo    410 |
NET | eth0      0% |  pcki 1076002 | pcko  493729 |  si   47 Kbps | so    2 Kbps |  erro       0 |
NET | lo      ---- |  pcki   47437 | pcko   47437 |  si    3 Kbps | so    3 Kbps |  erro       0 |
                          *** system and process activity since boot ***                    PAUSED
  PID   TID  THR  SYSCPU USRCPU  VGROW   RGROW  RDDSK  WRDSK  ST EXC S  CPUNR  CPU  CMD       1/12
  566     -    8   1m53s 65m00s 653.0M  528.2M  7356K   1.1G  N-   - S      0   6%  virtuoso-t
  501     -    2  14m31s 45m58s 364.8M  145.7M   432K 405.3G  N-   - R      3   5%  akonadi_agent_

Yes, thats 405,3GB for:

merkaba:~> ps aux | grep 501 | grep -v grep | grep -v atop
martin     501 63.2  1.8 373728 149232 ?       Dl   10:44  60:57 /usr/bin/akonadi_agent_launcher akonadi_maildir_resource akonadi_maildir_resource_0
merkaba:~> ps aux | grep 501 | grep -v grep | grep -v atop
martin     501 63.2  1.8 373728 149496 ?       Dl   10:44  60:59 /usr/bin/akonadi_agent_launcher akonadi_maildir_resource akonadi_maildir_resource_0
merkaba:~> ps aux | grep 501 | grep -v grep | grep -v atop
martin     501 63.2  1.8 373728 149496 ?       Dl   10:44  61:00 /usr/bin/akonadi_agent_launcher akonadi_maildir_resource akonadi_maildir_resource_0
merkaba:~> ps aux | grep 501 | grep -v grep | grep -v atop
martin     501 63.2  1.8 373728 149496 ?       Dl   10:44  61:00 /usr/bin/akonadi_agent_launcher akonadi_maildir_resource akonadi_maildir_resource_0
merkaba:~> ps aux | grep 501 | grep -v grep | grep -v atop
martin     501 63.2  1.8 373728 149496 ?       Rl   10:44  61:00 /usr/bin/akonadi_agent_launcher akonadi_maildir_resource akonadi_maildir_resource_0

Often in D state.

Akonadi has overwritten my Intel SSD 320 once already.

Expected Results:  
A *sane* amount of I/O.

merkaba:~> cat /proc/version
Linux version 3.9.0-tp520 (martin@merkaba) (gcc version 4.7.2 (Debian 4.7.2-5) ) #7 SMP PREEMPT Mon Apr 29 15:01:05 CEST 2013

I use BTRFS as home partition, but placed ~/.config/akonadi, ~/.local/share/akonadi and ~/.local/share/local-mail on Ext4 partition.
Comment 1 Martin Steigerwald 2013-05-01 10:34:10 UTC
Akonadi does not seem to make any progress in sorting the file_db_data mails into the Maildir:

martin@merkaba:/home2/martin#130> date ; du -sch Akonadi/* Nepomuk ; du -sch Akonadi/Datenbank/db_data Akonadi/Datenbank/file_db_data                    
Mi 1. Mai 12:31:13 CEST 2013
8,4G    Akonadi/Datenbank
276K    Akonadi/Konfiguration
349M    Akonadi/Mails
452M    Nepomuk
9,2G    insgesamt
2,4G    Akonadi/Datenbank/db_data
6,1G    Akonadi/Datenbank/file_db_data
8,4G    insgesamt

 ~/.local/share/local-mails is symlinked to Akonadi/Mails

~/.local/share/akonadi is symlinked to Akonadi/Datenbank

~/.config/akonadi is symlinked to Akonadi/Konfiguration

~/.kde/share/apps/nepomuk is symlinked to Nepomuk

This is to have all Akonadi related data (except calender and addresses) on Ext4, instead of BTRFS as suggested.
Comment 2 Martin Steigerwald 2013-05-01 10:34:35 UTC
It is setting at 349 MB mails for over an hour already.
Comment 3 Martin Steigerwald 2013-05-01 10:39:36 UTC
After

- akonadictl stop
- wait until notification that it really stopped (about a minute)
- akonadictl start

Akonadi seems to process file_db_data stuff:

martin@merkaba:/home2/martin> date ; du -sch Akonadi/* Nepomuk ; du -sch Akonadi/Datenbank/db_data Akonadi/Datenbank/file_db_data
Mi 1. Mai 12:38:09 CEST 2013
8,4G    Akonadi/Datenbank
27M     Akonadi/Konfiguration
410M    Akonadi/Mails
485M    Nepomuk
9,3G    insgesamt
2,4G    Akonadi/Datenbank/db_data
6,1G    Akonadi/Datenbank/file_db_data
8,4G    insgesamt
martin@merkaba:/home2/martin> date ; du -sch Akonadi/* Nepomuk ; du -sch Akonadi/Datenbank/db_data Akonadi/Datenbank/file_db_data
Mi 1. Mai 12:38:57 CEST 2013
8,4G    Akonadi/Datenbank
27M     Akonadi/Konfiguration
458M    Akonadi/Mails
487M    Nepomuk
9,4G    insgesamt
2,4G    Akonadi/Datenbank/db_data
6,1G    Akonadi/Datenbank/file_db_data
8,4G    insgesamt


If it now also sets read/unread status of imported mails correctly, that would be fine. I know I do not have >7500 unread mails in my inbox.
Comment 4 Martin Steigerwald 2013-05-01 19:20:58 UTC
Created attachment 79605 [details]
atopsar output during the time of high disk I/O usage
Comment 5 Martin Steigerwald 2013-05-01 19:22:50 UTC
Created attachment 79606 [details]
atop log file which can be used together with atopsar

Some reports:

- Disk utilization: atopsar -d -r atop_20130501

- Top 3 Disk using processes: atopsar -D -r atop_20130501

CPU stats are also in this file.
Comment 6 Martin Steigerwald 2013-05-01 19:25:46 UTC
Created attachment 79608 [details]
screenshot of atop with statistic since boot

akonadi maildir resource has written more than 450 GiB!
Comment 7 Martin Steigerwald 2013-05-01 19:28:42 UTC
Created attachment 79610 [details]
typical 10 seconds snapshot of atop with maildir agent doing lots of I/O

It usually did about 800 MiB during 10 seconds.

I had another attempt of migrating afterwards and so far it seems it was successful. I just put the contents of the old KMail-1 maildir - which doesn´t contain any mbox files - into ~/.local/share/local-mail and started with a clean configuration. I added most important filter rules and so far it seems to behave. Even address completion works :)

I keep mail indexing switched off for now however.
Comment 8 Martin Steigerwald 2015-03-12 12:20:13 UTC
This was still in Nepomuk times.

I am not sure whether its reproducable anymore with current versions and Baloo. And as my setup is long migrated frankly I do not care to reproduce it.

Thus closing. If anyone else sees this, or has this, feel free to reopen.