Profile and improve CPU usage

[probonopd]

Profile CPU usage to find out what causes appimaged to consume 100% CPU at startup for 10+ seconds.

For CPU bound applications:
Use a profiler in DEBUG mode to identify questionable parts of your code
Then switch to RELEASE mode and comment out the questionable sections of your code (stub it with nothing) until you see changes in performance.

https://stackoverflow.com/questions/375913/how-can-i-profile-c-code-running-on-linux/378024

[probonopd]

• https://github.com/KDAB/hotspot/releases
• https://github.com/jrfonseca/gprof2dot

We need a special build using special gcc options for profiling:

https://github.com/jrfonseca/gprof2dot#which-options-should-i-pass-to-gcc-when-compiling-for-profiling

[probonopd]

Interesting results in under 30 seconds of analysis using oprofile:

# xubuntu-16.04.1-desktop-amd64.iso

systemctl --user stop appimaged
sudo apt install -y oprofile
find $HOME -type f -name '*appimagekit*' -delete
sudo operf /usr/bin/appimaged -v
# Let it run until it quiesces (CPU usage drops)
opreport --symbols | head -n 20
(...)
samples  %        image name               app name                 symbol name
289921   12.6670  libc-2.23.so             appimaged                _int_malloc
288744   12.6156  libc-2.23.so             appimaged                _int_free
196628    8.5909  libc-2.23.so             appimaged                malloc
177278    7.7455  libc-2.23.so             appimaged                re_compile_internal
171381    7.4879  libc-2.23.so             appimaged                build_trtable
98853     4.3190  libc-2.23.so             appimaged                malloc_consolidate
82260     3.5940  libc-2.23.so             appimaged                free
66660     2.9125  libxml2.so.2.9.3         update-mime-database.real /usr/lib/x86_64-linux-gnu/libxml2.so.2.9.3
59574     2.6029  libc-2.23.so             appimaged                realloc
51104     2.2328  libc-2.23.so             appimaged                re_acquire_state_context
47284     2.0659  appimaged                appimaged                lzma_decode
43237     1.8891  libc-2.23.so             appimaged                calc_eclosure_iter
43129     1.8844  libc-2.23.so             appimaged                free_dfa_content
33326     1.4561  libc-2.23.so             appimaged                re_node_set_merge.part.16
33097     1.4460  libz.so.1.2.8            appimaged                /lib/x86_64-linux-gnu/libz.so.1.2.8
31545     1.3782  libc-2.23.so             appimaged                re_dfa_add_node
30962     1.3528  libc-2.23.so             appimaged                re_search_internal

This suggests that a lot of time is spent on Regex.
Already now, I love oprofile!

[probonopd]

Similar, linuxmint-18.1-cinnamon-64bit.iso:

systemctl --user stop appimaged
sudo apt install -y oprofile
find $HOME -type f -name '*appimagekit*' -delete
sudo operf /usr/bin/appimaged -v
# Let it run until it quiesces (CPU usage drops)
opreport --symbols | head -n 20
(...)
samples  %        image name               app name                 symbol name
298166   12.8835  libc-2.23.so             appimaged                _int_malloc
290919   12.5703  libc-2.23.so             appimaged                _int_free
198783    8.5892  libc-2.23.so             appimaged                malloc
178815    7.7264  libc-2.23.so             appimaged                re_compile_internal
173222    7.4848  libc-2.23.so             appimaged                build_trtable
100736    4.3527  libc-2.23.so             appimaged                malloc_consolidate
81232     3.5100  libc-2.23.so             appimaged                free
68335     2.9527  libxml2.so.2.9.3         update-mime-database.real /usr/lib/x86_64-linux-gnu/libxml2.so.2.9.3
60434     2.6113  libc-2.23.so             appimaged                realloc
51437     2.2225  libc-2.23.so             appimaged                re_acquire_state_context
47395     2.0479  appimaged                appimaged                lzma_decode
44080     1.9047  libc-2.23.so             appimaged                calc_eclosure_iter
43250     1.8688  libc-2.23.so             appimaged                free_dfa_content
33316     1.4396  libz.so.1.2.8            appimaged                /lib/x86_64-linux-gnu/libz.so.1.2.8
33233     1.4360  libc-2.23.so             appimaged                re_node_set_merge.part.16
32048     1.3848  libc-2.23.so             appimaged                re_dfa_add_node
31197     1.3480  libc-2.23.so             appimaged                re_search_internal

Seems like most time is spent on malloc and free (why?), and at least 20% of CPU time is spent on regex (including build_trtable, calc_eclosure_iter):

me@host ~ $ opreport --symbols | grep -e ' re_'

178815    7.7264  libc-2.23.so             appimaged                re_compile_internal
51437     2.2225  libc-2.23.so             appimaged                re_acquire_state_context
33233     1.4360  libc-2.23.so             appimaged                re_node_set_merge.part.16
32048     1.3848  libc-2.23.so             appimaged                re_dfa_add_node
31197     1.3480  libc-2.23.so             appimaged                re_search_internal
17208     0.7435  libc-2.23.so             appimaged                re_node_set_insert
13086     0.5654  libc-2.23.so             appimaged                re_compile_fastmap_iter.isra.26
11600     0.5012  libc-2.23.so             appimaged                re_string_reconstruct
4788      0.2069  libc-2.23.so             appimaged                re_string_context_at
4719      0.2039  libc-2.23.so             appimaged                re_acquire_state
3776      0.1632  libc-2.23.so             appimaged                re_node_set_add_intersect.part.18
1529      0.0661  libc-2.23.so             appimaged                re_node_set_contains.isra.3
920       0.0398  libc-2.23.so             appimaged                re_compile_fastmap

MIME is not a huge bottleneck here:

me@host ~ $ opreport --symbols | grep mime
(...)
68335     2.9527  libxml2.so.2.9.3         update-mime-database.real /usr/lib/x86_64-linux-gnu/libxml2.so.2.9.3
29447     1.2724  update-mime-database.real update-mime-database.real /usr/bin/update-mime-database.real
19588     0.8464  libc-2.23.so             update-mime-database.real malloc_consolidate
12706     0.5490  libc-2.23.so             update-mime-database.real _int_malloc
8470      0.3660  libc-2.23.so             update-mime-database.real _int_free
6639      0.2869  libc-2.23.so             update-mime-database.real malloc
5649      0.2441  libc-2.23.so             update-mime-database.real __GI___strcmp_ssse3

[probonopd]

deepin-15.5-amd64.iso:

samples  %        image name               app name                 symbol name
2809941  77.0336  libc-2.24.so             appimaged                /lib/x86_64-linux-gnu/libc-2.24.so
177760    4.8732  libxml2.so.2.9.4         update-mime-database.real /usr/lib/x86_64-linux-gnu/libxml2.so.2.9.4
167353    4.5879  libc-2.24.so             update-mime-database.real /lib/x86_64-linux-gnu/libc-2.24.so
95246     2.6111  appimaged                appimaged                lzma_decode
90290     2.4753  update-mime-database.real update-mime-database.real /usr/bin/update-mime-database.real
44537     1.2210  libz.so.1.2.8            appimaged                /lib/x86_64-linux-gnu/libz.so.1.2.8

[probonopd]

# xubuntu-18.04-desktop-amd64.iso

systemctl --user stop appimaged
sudo apt install -y oprofile
find $HOME -type f -name '*appimagekit*' -delete
sudo operf /usr/bin/appimaged -v
# Let it run until it quiesces (CPU usage drops)
opreport --symbols | head -n 20
(...)
samples  %        image name               app name                 symbol name
269956   12.7213  libc-2.27.so             operf                    free
249689   11.7662  libc-2.27.so             operf                    _int_malloc
200959    9.4699  libc-2.27.so             operf                    build_trtable
191166    9.0084  libc-2.27.so             operf                    re_compile_internal
110790    5.2208  libc-2.27.so             operf                    malloc
85642     4.0358  libc-2.27.so             operf                    malloc_consolidate
75837     3.5737  libxml2.so.2.9.4         update-mime-database     /usr/lib/x86_64-linux-gnu/libxml2.so.2.9.4
66128     3.1162  libc-2.27.so             operf                    realloc
54770     2.5810  libc-2.27.so             operf                    re_acquire_state_context
51748     2.4386  libc-2.27.so             operf                    free_dfa_content
48772     2.2983  libc-2.27.so             operf                    calc_eclosure_iter
48499     2.2854  appimaged                operf                    lzma_decode
34220     1.6126  libz.so.1.2.11           operf                    /lib/x86_64-linux-gnu/libz.so.1.2.11
31714     1.4945  libc-2.27.so             operf                    calloc
31197     1.4701  libc-2.27.so             operf                    re_search_internal
29388     1.3849  libc-2.27.so             operf                    re_dfa_add_node
28154     1.3267  update-mime-database     update-mime-database     /usr/bin/update-mime-database

[probonopd]

Possibly the results above are not correct, and the actual issue may be sqfs_.
echo 0 | sudo tee /proc/sys/kernel/kptr_restrict may be needed.

[probonopd]

Could be that mksquashfs -noInodeCompression helps?

[probonopd]

Related:

• Use tree search instead of linear search on traversed tree for more efficient extraction of single files libappimage#34
• Replace regular expressions for performance libappimage#32