~tpetazzoni


#299 Slow startup with heavy maildir 17 days ago

Comment by ~tpetazzoni on ~rjarry/aerc

It wasn't using IMAP, but a local store, aka maildir://.

#299 Slow startup with heavy maildir a month ago

Comment by ~tpetazzoni on ~rjarry/aerc

Output of first command: https://paste.ack.tf/847681 Output of second command: https://paste.ack.tf/6c88b8

Note that these captures have been done with the latest master of aerc, while the previous capture was done with whatever aerc version was available in Fedora 40 (which most likely wasn't the latest)

#299 Slow startup with heavy maildir a month ago

Comment by ~tpetazzoni on ~rjarry/aerc

Sorry for the delay, here is the output of "perf report" as requested. I have no idea if this output is useful/relevant, let me know.

# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 3K of event 'cpu_atom/cycles/Pu'
# Event count (approx.): 1797132652
#
# Children      Self  Command  Shared Object         Symbol                                                                                                                                                                       
# ........  ........  .......  ....................  .............................................................................................................................................................................
#
    75.62%     0.00%  aerc     [unknown]             [.] 0x01ffffffffffff7f
            |
            ---0x1ffffffffffff7f
               |          
               |--74.65%--runtime.systemstack.abi0
               |          |          
               |          |--71.80%--runtime.gcBgMarkWorker.func2
               |          |          |          
               |          |          |--37.68%--runtime.gcDrainMarkWorkerIdle (inlined)
               |          |          |          runtime.gcDrain
               |          |          |          |          
               |          |          |           --37.53%--runtime.scanobject
               |          |          |                     |          
               |          |          |                     |--19.22%--runtime.greyobject
               |          |          |                     |          |          
               |          |          |                     |          |--10.02%--runtime.markBits.setMarked (inlined)
               |          |          |                     |          |          
               |          |          |                     |          |--5.98%--runtime.(*mspan).markBitsForIndex (inlined)
               |          |          |                     |          |          runtime.(*gcBits).bitp (inlined)
               |          |          |                     |          |          |          
               |          |          |                     |          |           --5.37%--runtime.(*gcBits).bytep (inlined)
               |          |          |                     |          |          
               |          |          |                     |           --0.63%--runtime.pageIndexOf (inlined)
               |          |          |                     |          
               |          |          |                     |--9.95%--runtime.findObject
               |          |          |                     |          |          
               |          |          |                     |          |--4.40%--runtime.(*mSpanStateBox).get (inlined)
               |          |          |                     |          |          |          
               |          |          |                     |          |           --4.26%--runtime/internal/atomic.(*Uint8).Load (inlined)
               |          |          |                     |          |          
               |          |          |                     |          |--2.25%--runtime.spanOf (inlined)
               |          |          |                     |          |          
               |          |          |                     |           --0.65%--runtime.(*mspan).base (inlined)
               |          |          |                     |          
               |          |          |                     |--1.04%--runtime.typePointers.nextFast (inlined)
               |          |          |                     |          
               |          |          |                      --0.72%--runtime.typePointers.next
               |          |          |          
               |          |           --34.12%--runtime.gcDrainMarkWorkerDedicated (inlined)
               |          |                     runtime.gcDrain
               |          |                     |          
               |          |                     |--33.12%--runtime.scanobject
               |          |                     |          |          
               |          |                     |          |--16.59%--runtime.greyobject
               |          |                     |          |          |          
               |          |                     |          |          |--8.65%--runtime.markBits.setMarked (inlined)
               |          |                     |          |          |          
               |          |                     |          |          |--4.58%--runtime.(*mspan).markBitsForIndex (inlined)
               |          |                     |          |          |          |          
               |          |                     |          |          |           --4.55%--runtime.(*gcBits).bitp (inlined)
               |          |                     |          |          |                     |          
               |          |                     |          |          |                      --4.12%--runtime.(*gcBits).bytep (inlined)
               |          |                     |          |          |          
               |          |                     |          |           --0.67%--runtime.pageIndexOf (inlined)
               |          |                     |          |          
               |          |                     |          |--7.05%--runtime.findObject
               |          |                     |          |          |          
               |          |                     |          |          |--3.02%--runtime.(*mSpanStateBox).get (inlined)
               |          |                     |          |          |          |          
               |          |                     |          |          |           --2.98%--runtime/internal/atomic.(*Uint8).Load (inlined)
               |          |                     |          |          |          
               |          |                     |          |           --1.66%--runtime.spanOf (inlined)
               |          |                     |          |          
               |          |                     |          |--1.33%--runtime.typePointers.next
               |          |                     |          |          
               |          |                     |           --1.02%--runtime.typePointers.nextFast (inlined)
               |          |                     |          
               |          |                      --0.68%--runtime.markroot
               |          |          
               |          |--1.26%--runtime.(*sweepLocked).sweep.(*mheap).freeSpan.func3
               |          |          |          
               |          |           --1.07%--runtime.(*mheap).freeSpanLocked
               |          |                     |          
               |          |                      --0.66%--runtime.(*pageAlloc).free
               |          |          
               |           --0.81%--runtime.gcAssistAlloc.func1
               |                     runtime.gcAssistAlloc1
               |                     runtime.gcDrainN
               |                     |          
               |                      --0.80%--runtime.scanobject
               |          
                --0.93%--runtime.mcall
                          runtime.park_m
                          runtime.schedule
                          |          
                           --0.89%--runtime.findRunnable

    74.65%     0.03%  aerc     aerc                  [.] runtime.systemstack.abi0
            |          
             --74.63%--runtime.systemstack.abi0
                       |          
                       |--71.77%--runtime.gcBgMarkWorker.func2
                       |          |          
                       |          |--37.68%--runtime.gcDrainMarkWorkerIdle (inlined)
                       |          |          runtime.gcDrain
                       |          |          |          
                       |          |           --37.53%--runtime.scanobject
                       |          |                     |          
                       |          |                     |--19.22%--runtime.greyobject
                       |          |                     |          |          
                       |          |                     |          |--10.02%--runtime.markBits.setMarked (inlined)
                       |          |                     |          |          
                       |          |                     |          |--5.98%--runtime.(*mspan).markBitsForIndex (inlined)
                       |          |                     |          |          runtime.(*gcBits).bitp (inlined)
                       |          |                     |          |          |          
                       |          |                     |          |           --5.37%--runtime.(*gcBits).bytep (inlined)
                       |          |                     |          |          
                       |          |                     |           --0.63%--runtime.pageIndexOf (inlined)
                       |          |                     |          
                       |          |                     |--9.95%--runtime.findObject
                       |          |                     |          |          
                       |          |                     |          |--4.40%--runtime.(*mSpanStateBox).get (inlined)
                       |          |                     |          |          |          
                       |          |                     |          |           --4.26%--runtime/internal/atomic.(*Uint8).Load (inlined)
                       |          |                     |          |          
                       |          |                     |          |--2.25%--runtime.spanOf (inlined)
                       |          |                     |          |          
                       |          |                     |           --0.65%--runtime.(*mspan).base (inlined)
                       |          |                     |          
                       |          |                     |--1.04%--runtime.typePointers.nextFast (inlined)
                       |          |                     |          
                       |          |                      --0.72%--runtime.typePointers.next
                       |          |          
                       |           --34.09%--runtime.gcDrainMarkWorkerDedicated (inlined)
                       |                     runtime.gcDrain
                       |                     |          
                       |                     |--33.12%--runtime.scanobject
                       |                     |          |          
                       |                     |          |--16.59%--runtime.greyobject
                       |                     |          |          |          
                       |                     |          |          |--8.65%--runtime.markBits.setMarked (inlined)
                       |                     |          |          |          
                       |                     |          |          |--4.58%--runtime.(*mspan).markBitsForIndex (inlined)
                       |                     |          |          |          |          
                       |                     |          |          |           --4.55%--runtime.(*gcBits).bitp (inlined)
                       |                     |          |          |                     |          
                       |                     |          |          |                      --4.12%--runtime.(*gcBits).bytep (inlined)
                       |                     |          |          |          
                       |                     |          |           --0.67%--runtime.pageIndexOf (inlined)
                       |                     |          |          
                       |                     |          |--7.05%--runtime.findObject
                       |                     |          |          |          
                       |                     |          |          |--3.02%--runtime.(*mSpanStateBox).get (inlined)
                       |                     |          |          |          |          
                       |                     |          |          |           --2.98%--runtime/internal/atomic.(*Uint8).Load (inlined)
                       |                     |          |          |          
                       |                     |          |           --1.66%--runtime.spanOf (inlined)
                       |                     |          |          
                       |                     |          |--1.33%--runtime.typePointers.next
                       |                     |          |          
                       |                     |           --1.02%--runtime.typePointers.nextFast (inlined)
                       |                     |          
                       |                      --0.68%--runtime.markroot
                       |          
                       |--1.26%--runtime.(*sweepLocked).sweep.(*mheap).freeSpan.func3
                       |          |          
                       |           --1.07%--runtime.(*mheap).freeSpanLocked
                       |                     |          
                       |                      --0.66%--runtime.(*pageAlloc).free
                       |          
                        --0.81%--runtime.gcAssistAlloc.func1
                                  runtime.gcAssistAlloc1
                                  runtime.gcDrainN
                                  |          
                                   --0.80%--runtime.scanobject

    72.10%    16.13%  aerc     aerc                  [.] runtime.scanobject
            |          
            |--56.30%--runtime.scanobject
            |          |          
            |          |--36.09%--runtime.greyobject
            |          |          |          
            |          |          |--18.85%--runtime.markBits.setMarked (inlined)
            |          |          |          
            |          |          |--10.65%--runtime.(*mspan).markBitsForIndex (inlined)
            |          |          |          |          
            |          |          |           --10.62%--runtime.(*gcBits).bitp (inlined)
            |          |          |                     |          
            |          |          |                      --9.58%--runtime.(*gcBits).bytep (inlined)
            |          |          |          
            |          |          |--1.33%--runtime.pageIndexOf (inlined)
            |          |          |          
            |          |          |--0.77%--runtime.markBits.isMarked (inlined)
            |          |          |          
            |          |           --0.57%--runtime.(*mspan).base (inlined)
            |          |          
            |          |--17.18%--runtime.findObject
            |          |          |          
            |          |          |--7.42%--runtime.(*mSpanStateBox).get (inlined)

#299 Slow startup with heavy maildir a month ago

Ticket created by ~tpetazzoni on ~rjarry/aerc

I have a locally stored maildir with 3.7 millions e-mails spread in ~50 folders. aerc spends ~15 seconds at startup with a spinning [...] before it shows any e-mail.

Is there something that can be done to improve the startup time?

The strace -c output looks like this:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------------------
 76,17   58,883267        9050      6506       421 futex
  6,63    5,126167       28478       180         1 read
  6,58    5,084948        2867      1773         2 epoll_pwait
  6,23    4,818495         326     14776           nanosleep
  3,86    2,982285          43     68400           getdents64
  0,20    0,158011          38      4098           tgkill
  0,12    0,092559          38      2390           madvise
  0,06    0,048912          11      4098           getpid
  0,06    0,043334          10      4098        10 rt_sigreturn
  0,02    0,017345           6      2520           sched_yield
  0,01    0,010641           9      1093       110 newfstatat
  0,01    0,006921          89        77           mprotect
  0,01    0,005638          16       339           mmap
  0,01    0,004878          21       231           write
  0,01    0,004832          29       164           rt_sigprocmask
  0,00    0,002931         117        25           clone3
  0,00    0,002803           2      1350           fcntl
  0,00    0,001915           5       366         1 openat
  0,00    0,001754           4       366           close
  0,00    0,001637          31        52           sigaltstack
  0,00    0,000954          36        26           set_robust_list
  0,00    0,000900          34        26           gettid
  0,00    0,000743          35        21           munmap
  0,00    0,000690          26        26           rseq
  0,00    0,000659           1       341       333 epoll_ctl
  0,00    0,000446           3       114           rt_sigaction
  0,00    0,000147           4        31           fstat
  0,00    0,000093          46         2           socket
  0,00    0,000079          26         3         2 unlinkat
  0,00    0,000066          66         1           bind
  0,00    0,000055          18         3           inotify_add_watch
  0,00    0,000047          47         1         1 connect
  0,00    0,000046          46         1           getrlimit
  0,00    0,000037          37         1         1 accept4
  0,00    0,000022           3         7           ioctl
  0,00    0,000021          10         2           statfs
  0,00    0,000018          18         1           pipe2
  0,00    0,000016          16         1           setrlimit
  0,00    0,000014           4         3           brk
  0,00    0,000009           9         1           setsockopt
  0,00    0,000008           4         2           sched_getaffinity
  0,00    0,000008           8         1           epoll_create1
  0,00    0,000007           3         2           prlimit64
  0,00    0,000006           3         2         1 access
  0,00    0,000005           5         1           arch_prctl
  0,00    0,000005           5         1           set_tid_address
  0,00    0,000004           4         1           getrandom
  0,00    0,000003           3         1           listen
  0,00    0,000002           2         1           getsockname
  0,00    0,000000           0         2           pread64
  0,00    0,000000           0         1           execve
  0,00    0,000000           0         1           inotify_init1
  0,00    0,000000           0         1           faccessat2
------ ----------- ----------- --------- --------- ------------------
100,00   77,304383         680    113531       883 total

BTW, thanks for your great talk at FOSDEM 2025, I was in the room!