kiwix-serve hangs on search on Pi with SO ZIM

Popolechien commented 2 years ago

We made a special Offspot image for use in a RaspberryPi that consists of a docker setup (using balenaEngine and docker-compose) on a Pi4 4GB that serves 3 containers:

kiwix-serve
a python app
a reverse proxy (Caddy)

Apparently, when the user searches anything inside kiwix-serve, he never receives an answer and the kiwix-serve process hangs. The rest of the system is apparently OK.

User description:

the one issue i am having is the search. searching never returns results. even when i close the browser and return to the home page, the search seems to have locked up the kiwix server. i can still log into the pi console so it looks like only the kiwix process is hung. i tried broad search terms like array and what i think is a narrow search term like chucknorris with the same thing happening. after rebooting, kiwix works properly, but any search seems to hang it again.

Important details:

Very large ZIM file (64GB)
ZIM stored on an exFAT formatted partition of a 128GB microSD card
using raspiOS (buster) lite
using docker-compose
using balenaEngine
4GB RAM on the Pi 4.
using a nightly of kiwix-serve (libzim7) as of 2021-12-26 (https://github.com/kiwix/libkiwix/commit/843d315b93ffae360e76088ec16bc32fc7bec71e), most probably using kiwix-tools_linux-armhf-2021-12-26.tar.gz

kelson42 commented 2 years ago

I tried to reproduce the problem on my workstation without success. I have an i7-4770K CPU @ 3.50GHz and an old SSD. First time research "array" gives a result in ~1.5s and not more than 1GB of RAM is used. We really need to test on an RPI (ideally of the same kind and with the same kind of SD card).

rgaudin commented 2 years ago

Additional information from user:

during a search, mount.exfat is pegging the cpu

attached are two top output files, one at idle and one during a search

top-search

top - 19:19:23 up 17 min,  1 user,  load average: 1.30, 0.33, 0.17
Tasks: 127 total,   2 running, 125 sleeping,   0 stopped,   0 zombie
%Cpu(s):  7.2 us, 23.2 sy,  0.0 ni, 21.7 id, 47.8 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3838.7 total,   2635.3 free,    233.2 used,    970.2 buff/cache
MiB Swap:    100.0 total,    100.0 free,      0.0 used.   3478.8 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
  311 root      20   0    3080   1492    944 R  93.8   0.0   0:26.22 mount.exfat
 2440 pi        20   0   10184   2912   2532 R   6.2   0.1   0:00.02 top
    1 root      20   0   34684   7984   6260 S   0.0   0.2   0:05.34 systemd
    2 root      20   0       0      0      0 S   0.0   0.0   0:00.01 kthreadd
    3 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_gp
    4 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_par_gp
    8 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mm_percpu_wq
    9 root      20   0       0      0      0 S   0.0   0.0   0:00.00 rcu_tasks_rude_
   10 root      20   0       0      0      0 S   0.0   0.0   0:00.00 rcu_tasks_trace
   11 root      20   0       0      0      0 S   0.0   0.0   0:00.20 ksoftirqd/0
   12 root      20   0       0      0      0 I   0.0   0.0   0:00.16 rcu_sched
   13 root      rt   0       0      0      0 S   0.0   0.0   0:00.00 migration/0
   14 root      20   0       0      0      0 S   0.0   0.0   0:00.00 cpuhp/0
   15 root      20   0       0      0      0 S   0.0   0.0   0:00.00 cpuhp/1
   16 root      rt   0       0      0      0 S   0.0   0.0   0:00.00 migration/1
   17 root      20   0       0      0      0 S   0.0   0.0   0:00.16 ksoftirqd/1
   20 root      20   0       0      0      0 S   0.0   0.0   0:00.00 cpuhp/2
   21 root      rt   0       0      0      0 S   0.0   0.0   0:00.00 migration/2
   22 root      20   0       0      0      0 S   0.0   0.0   0:00.14 ksoftirqd/2
   25 root      20   0       0      0      0 S   0.0   0.0   0:00.00 cpuhp/3
   26 root      rt   0       0      0      0 S   0.0   0.0   0:00.00 migration/3
   27 root      20   0       0      0      0 S   0.0   0.0   0:00.18 ksoftirqd/3
   30 root      20   0       0      0      0 S   0.0   0.0   0:00.00 kdevtmpfs
   31 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 netns
   34 root      20   0       0      0      0 S   0.0   0.0   0:00.00 kauditd
   36 root      20   0       0      0      0 S   0.0   0.0   0:00.00 khungtaskd
   37 root      20   0       0      0      0 S   0.0   0.0   0:00.00 oom_reaper
   38 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 writeback
   39 root      20   0       0      0      0 S   0.0   0.0   0:00.09 kcompactd0
   57 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kblockd
   58 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 blkcg_punt_bio
   59 root     -51   0       0      0      0 S   0.0   0.0   0:00.00 watchdogd
   61 root       0 -20       0      0      0 I   0.0   0.0   0:00.23 kworker/0:1H-kblockd
   62 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rpciod
   64 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 xprtiod
   65 root      20   0       0      0      0 S   0.0   0.0   0:00.28 kswapd0
   66 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 nfsiod
   67 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kthrotld
   68 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 iscsi_eh
   69 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 iscsi_destroy
   70 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 nvme-wq
   71 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 nvme-reset-wq
   72 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 nvme-delete-wq
   73 root      20   0       0      0      0 I   0.0   0.0   0:00.00 kworker/u8:1-ext4-rsv-conversion
   76 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 DWC Notificatio
   77 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 uas
   78 root       1 -19       0      0      0 S   0.0   0.0   0:00.00 vchiq-slot/0
   79 root       1 -19       0      0      0 S   0.0   0.0   0:00.00 vchiq-recy/0
   80 root       0 -20       0      0      0 S   0.0   0.0   0:00.00 vchiq-sync/0
   81 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 zswap-shrink
   84 root      20   0       0      0      0 I   0.0   0.0   0:00.11 kworker/0:5-events
   85 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 sdhci
   86 root     -51   0       0      0      0 S   0.0   0.0   0:00.00 irq/47-mmc0
   88 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmc_complete
   89 root       0 -20       0      0      0 I   0.0   0.0   0:00.29 kworker/2:1H-kblockd
   90 root      20   0       0      0      0 S   0.0   0.0   0:00.04 jbd2/mmcblk0p2-
   91 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 ext4-rsv-conver
   92 root       0 -20       0      0      0 I   0.0   0.0   0:00.01 kworker/2:2H
   93 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 ipv6_addrconf
   95 root       0 -20       0      0      0 I   0.0   0.0   0:00.20 kworker/1:1H-kblockd
   99 root       0 -20       0      0      0 I   0.0   0.0   0:00.19 kworker/3:1H-kblockd
  118 root      20   0   21204   7456   6632 S   0.0   0.2   0:00.86 systemd-journal
  121 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/1:2H
  142 root       0 -20       0      0      0 I   0.0   0.0   0:00.33 kworker/0:2H-mmc_complete
  152 root      20   0       0      0      0 I   0.0   0.0   0:00.27 kworker/u8:2-events_unbound
  154 root      20   0   17996   3740   2928 S   0.0   0.1   0:00.60 systemd-udevd
  185 root      20   0       0      0      0 S   0.0   0.0   0:00.00 vchiq-keep/0
  187 root      10 -10       0      0      0 S   0.0   0.0   0:00.00 SMIO
  202 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  206 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  207 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  211 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  228 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  257 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 cfg80211
  261 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_bin
  262 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_render
  263 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_tfu
  264 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_csd
  266 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_cache_clean
  267 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 brcmf_wq/mmc1:0
  268 root      20   0       0      0      0 I   0.0   0.0   0:00.02 kworker/2:3-mm_percpu_wq
  269 root      20   0       0      0      0 I   0.0   0.0   0:00.16 kworker/2:4-cgroup_destroy
  270 root      20   0       0      0      0 S   0.0   0.0   0:00.00 brcmf_wdog/mmc1
  274 root     -51   0       0      0      0 S   0.0   0.0   0:00.00 card1-crtc0
  336 systemd+  20   0   22380   2824   2240 S   0.0   0.1   0:00.47 systemd-timesyn
  374 root      39  19    3692    784    676 S   0.0   0.0   0:00.03 alsactl
  380 avahi     20   0    5892   2836   2520 S   0.0   0.1   0:00.30 avahi-daemon
  384 root      20   0   27656     80      0 S   0.0   0.0   0:00.08 rngd
  388 root      20   0   25512   2744   2432 S   0.0   0.1   0:00.18 rsyslogd
  389 nobody    20   0    4320   2076   1904 S   0.0   0.1   0:00.03 thd
  390 message+  20   0    6556   3020   2744 S   0.0   0.1   0:00.32 dbus-daemon
  398 root      20   0   10708   3752   3380 S   0.0   0.1   0:00.05 wpa_supplicant
  402 root      20   0    7948   2340   2160 S   0.0   0.1   0:00.02 cron
  405 avahi     20   0    5768    252      0 S   0.0   0.0   0:00.00 avahi-daemon
  407 root      20   0   13140   5768   5104 S   0.0   0.1   0:00.20 systemd-logind
  512 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/u9:1-hci0
  514 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/u9:2-hci0
  515 root      20   0    2136    112      0 S   0.0   0.0   0:00.00 hciattach
  517 root      20   0       0      0      0 I   0.0   0.0   0:00.12 kworker/3:3-mm_percpu_wq
  528 root      20   0    9536   3344   3060 S   0.0   0.1   0:00.03 bluetoothd
  579 root      20   0 1031304  52704  25168 S   0.0   1.3   0:07.81 balena-engine-d
  603 root      20   0  982448  49224  24008 S   0.0   1.3   0:04.61 balena-engine-c
  658 root      20   0   10968   2028   1480 S   0.0   0.1   0:00.03 wpa_supplicant
  692 root      20   0    3364   2624   1688 S   0.0   0.1   0:00.29 dhcpcd
  698 root      20   0    5620   2760   2312 S   0.0   0.1   0:00.13 login
 1863 root      20   0  924052  42672  21256 S   0.0   1.1   0:02.63 balena-engine-c
 1923 root      20   0  916112  42840  22288 S   0.0   1.1   0:00.71 balena-engine-p
 1934 root      20   0     200      4      0 S   0.0   0.0   0:00.13 dumb-init
 1940 root      20   0  924052  44816  23360 S   0.0   1.1   0:02.52 balena-engine-c
 1978 root      20   0  825008  27248  21256 S   0.0   0.7   0:01.08 caddy
 2092 root      20   0  581200 526356 522428 S   0.0  13.4   0:01.59 kiwix-serve
 2209 root      20   0  924052  44828  23532 S   0.0   1.1   0:02.65 balena-engine-c
 2225 root      20   0   21560  17596   5696 S   0.0   0.4   0:01.19 gunicorn
 2330 root      20   0   33196  26040   7232 S   0.0   0.7   0:02.94 gunicorn
 2369 root      20   0       0      0      0 I   0.0   0.0   0:00.05 kworker/1:0-events_power_efficient
 2370 root      20   0       0      0      0 I   0.0   0.0   0:00.09 kworker/0:1-events_power_efficient
 2371 root      20   0       0      0      0 I   0.0   0.0   0:00.11 kworker/1:2-events_power_efficient
 2382 root      20   0       0      0      0 I   0.0   0.0   0:00.00 kworker/3:0
 2386 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/3:0H
 2389 root      20   0       0      0      0 I   0.0   0.0   0:00.03 kworker/2:0-mm_percpu_wq
 2393 pi        20   0   14700   6516   5672 S   0.0   0.2   0:00.11 systemd
 2394 pi        20   0   36224   1896     64 S   0.0   0.0   0:00.00 (sd-pam)
 2398 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/2:0H
 2404 pi        20   0    8364   3596   2784 S   0.0   0.1   0:00.16 bash
 2434 root      20   0       0      0      0 I   0.0   0.0   0:00.01 kworker/0:0-events
 2435 root      20   0       0      0      0 I   0.0   0.0   0:00.02 kworker/1:1-events_power_efficient
 2439 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/0:0H

top-idle

top - 19:16:59 up 15 min,  1 user,  load average: 0.00, 0.04, 0.09
Tasks: 128 total,   1 running, 127 sleeping,   0 stopped,   0 zombie
%Cpu(s):  2.6 us,  3.9 sy,  0.0 ni, 93.4 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3838.7 total,   2646.6 free,    229.3 used,    962.9 buff/cache
MiB Swap:    100.0 total,    100.0 free,      0.0 used.   3482.7 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
 2420 pi        20   0   10184   2972   2592 R  11.1   0.1   0:00.04 top
    1 root      20   0   34684   7984   6260 S   0.0   0.2   0:05.33 systemd
    2 root      20   0       0      0      0 S   0.0   0.0   0:00.01 kthreadd
    3 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_gp
    4 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_par_gp
    8 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mm_percpu_wq
    9 root      20   0       0      0      0 S   0.0   0.0   0:00.00 rcu_tasks_rude_
   10 root      20   0       0      0      0 S   0.0   0.0   0:00.00 rcu_tasks_trace
   11 root      20   0       0      0      0 S   0.0   0.0   0:00.19 ksoftirqd/0
   12 root      20   0       0      0      0 I   0.0   0.0   0:00.15 rcu_sched
   13 root      rt   0       0      0      0 S   0.0   0.0   0:00.00 migration/0
   14 root      20   0       0      0      0 S   0.0   0.0   0:00.00 cpuhp/0
   15 root      20   0       0      0      0 S   0.0   0.0   0:00.00 cpuhp/1
   16 root      rt   0       0      0      0 S   0.0   0.0   0:00.00 migration/1
   17 root      20   0       0      0      0 S   0.0   0.0   0:00.16 ksoftirqd/1
   20 root      20   0       0      0      0 S   0.0   0.0   0:00.00 cpuhp/2
   21 root      rt   0       0      0      0 S   0.0   0.0   0:00.00 migration/2
   22 root      20   0       0      0      0 S   0.0   0.0   0:00.14 ksoftirqd/2
   25 root      20   0       0      0      0 S   0.0   0.0   0:00.00 cpuhp/3
   26 root      rt   0       0      0      0 S   0.0   0.0   0:00.00 migration/3
   27 root      20   0       0      0      0 S   0.0   0.0   0:00.18 ksoftirqd/3
   30 root      20   0       0      0      0 S   0.0   0.0   0:00.00 kdevtmpfs
   31 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 netns
   33 root      20   0       0      0      0 I   0.0   0.0   0:00.25 kworker/1:1-events
   34 root      20   0       0      0      0 S   0.0   0.0   0:00.00 kauditd
   36 root      20   0       0      0      0 S   0.0   0.0   0:00.00 khungtaskd
   37 root      20   0       0      0      0 S   0.0   0.0   0:00.00 oom_reaper
   38 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 writeback
   39 root      20   0       0      0      0 S   0.0   0.0   0:00.08 kcompactd0
   57 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kblockd
   58 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 blkcg_punt_bio
   59 root     -51   0       0      0      0 S   0.0   0.0   0:00.00 watchdogd
   61 root       0 -20       0      0      0 I   0.0   0.0   0:00.23 kworker/0:1H-kblockd
   62 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rpciod
   64 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 xprtiod
   65 root      20   0       0      0      0 S   0.0   0.0   0:00.28 kswapd0
   66 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 nfsiod
   67 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kthrotld
   68 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 iscsi_eh
   69 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 iscsi_destroy
   70 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 nvme-wq
   71 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 nvme-reset-wq
   72 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 nvme-delete-wq
   73 root      20   0       0      0      0 I   0.0   0.0   0:00.00 kworker/u8:1-ext4-rsv-conversion
   75 root      20   0       0      0      0 I   0.0   0.0   0:00.07 kworker/3:1-events
   76 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 DWC Notificatio
   77 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 uas
   78 root       1 -19       0      0      0 S   0.0   0.0   0:00.00 vchiq-slot/0
   79 root       1 -19       0      0      0 S   0.0   0.0   0:00.00 vchiq-recy/0
   80 root       0 -20       0      0      0 S   0.0   0.0   0:00.00 vchiq-sync/0
   81 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 zswap-shrink
   84 root      20   0       0      0      0 I   0.0   0.0   0:00.11 kworker/0:5-events
   85 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 sdhci
   86 root     -51   0       0      0      0 S   0.0   0.0   0:00.00 irq/47-mmc0
   88 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmc_complete
   89 root       0 -20       0      0      0 I   0.0   0.0   0:00.29 kworker/2:1H-kblockd
   90 root      20   0       0      0      0 S   0.0   0.0   0:00.04 jbd2/mmcblk0p2-
   91 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 ext4-rsv-conver
   92 root       0 -20       0      0      0 I   0.0   0.0   0:00.01 kworker/2:2H
   93 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 ipv6_addrconf
   95 root       0 -20       0      0      0 I   0.0   0.0   0:00.20 kworker/1:1H-kblockd
   99 root       0 -20       0      0      0 I   0.0   0.0   0:00.19 kworker/3:1H-kblockd
  110 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/3:2H
  118 root      20   0   21196   7444   6628 S   0.0   0.2   0:00.85 systemd-journal
  121 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/1:2H
  142 root       0 -20       0      0      0 I   0.0   0.0   0:00.33 kworker/0:2H-mmc_complete
  152 root      20   0       0      0      0 I   0.0   0.0   0:00.26 kworker/u8:2-events_unbound
  154 root      20   0   17996   3740   2928 S   0.0   0.1   0:00.60 systemd-udevd
  185 root      20   0       0      0      0 S   0.0   0.0   0:00.00 vchiq-keep/0
  187 root      10 -10       0      0      0 S   0.0   0.0   0:00.00 SMIO
  202 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  206 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  207 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  211 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  228 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mmal-vchiq
  257 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 cfg80211
  261 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_bin
  262 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_render
  263 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_tfu
  264 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_csd
  266 root      -2   0       0      0      0 S   0.0   0.0   0:00.00 v3d_cache_clean
  267 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 brcmf_wq/mmc1:0
  268 root      20   0       0      0      0 I   0.0   0.0   0:00.02 kworker/2:3-mm_percpu_wq
  269 root      20   0       0      0      0 I   0.0   0.0   0:00.16 kworker/2:4-cgroup_destroy
  270 root      20   0       0      0      0 S   0.0   0.0   0:00.00 brcmf_wdog/mmc1
  274 root     -51   0       0      0      0 S   0.0   0.0   0:00.00 card1-crtc0
  311 root      20   0    3080   1492    944 S   0.0   0.0   0:08.47 mount.exfat
  336 systemd+  20   0   22380   2824   2240 S   0.0   0.1   0:00.45 systemd-timesyn
  374 root      39  19    3692    784    676 S   0.0   0.0   0:00.03 alsactl
  380 avahi     20   0    5892   2836   2520 S   0.0   0.1   0:00.30 avahi-daemon
  384 root      20   0   27656     80      0 S   0.0   0.0   0:00.08 rngd
  388 root      20   0   25512   2744   2432 S   0.0   0.1   0:00.18 rsyslogd
  389 nobody    20   0    4320   2076   1904 S   0.0   0.1   0:00.03 thd
  390 message+  20   0    6556   3020   2744 S   0.0   0.1   0:00.32 dbus-daemon
  398 root      20   0   10708   3752   3380 S   0.0   0.1   0:00.05 wpa_supplicant
  402 root      20   0    7948   2340   2160 S   0.0   0.1   0:00.02 cron
  405 avahi     20   0    5768    252      0 S   0.0   0.0   0:00.00 avahi-daemon
  407 root      20   0   13140   5768   5104 S   0.0   0.1   0:00.20 systemd-logind
  512 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/u9:1-hci0
  514 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/u9:2-hci0
  515 root      20   0    2136    112      0 S   0.0   0.0   0:00.00 hciattach
  517 root      20   0       0      0      0 I   0.0   0.0   0:00.12 kworker/3:3-events
  528 root      20   0    9536   3344   3060 S   0.0   0.1   0:00.03 bluetoothd
  579 root      20   0 1031304  52704  25168 S   0.0   1.3   0:07.20 balena-engine-d
  603 root      20   0  982448  49224  24008 S   0.0   1.3   0:04.12 balena-engine-c
  658 root      20   0   10968   2028   1480 S   0.0   0.1   0:00.03 wpa_supplicant
  692 root      20   0    3364   2624   1688 S   0.0   0.1   0:00.28 dhcpcd
  698 root      20   0    5620   2760   2312 S   0.0   0.1   0:00.13 login
 1863 root      20   0  924052  42672  21256 S   0.0   1.1   0:02.32 balena-engine-c
 1923 root      20   0  916112  42840  22288 S   0.0   1.1   0:00.65 balena-engine-p
 1934 root      20   0     200      4      0 S   0.0   0.0   0:00.13 dumb-init
 1940 root      20   0  924052  44816  23360 S   0.0   1.1   0:02.20 balena-engine-c
 1978 root      20   0  825008  26568  21048 S   0.0   0.7   0:00.87 caddy
 2092 root      20   0   54764   8964   6888 S   0.0   0.2   0:00.81 kiwix-serve
 2209 root      20   0  924052  44828  23532 S   0.0   1.1   0:02.33 balena-engine-c
 2225 root      20   0   21560  17596   5696 S   0.0   0.4   0:01.15 gunicorn
 2330 root      20   0   33196  26040   7232 S   0.0   0.7   0:02.66 gunicorn
 2368 root      20   0       0      0      0 I   0.0   0.0   0:00.08 kworker/0:0-events_power_efficient
 2369 root      20   0       0      0      0 I   0.0   0.0   0:00.05 kworker/1:0-events_power_efficient
 2370 root      20   0       0      0      0 I   0.0   0.0   0:00.07 kworker/0:1-events
 2371 root      20   0       0      0      0 I   0.0   0.0   0:00.09 kworker/1:2-events_power_efficient
 2382 root      20   0       0      0      0 I   0.0   0.0   0:00.00 kworker/3:0
 2386 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/3:0H
 2389 root      20   0       0      0      0 I   0.0   0.0   0:00.00 kworker/2:0-events
 2393 pi        20   0   14700   6516   5672 S   0.0   0.2   0:00.11 systemd
 2394 pi        20   0   36224   1896     64 S   0.0   0.0   0:00.00 (sd-pam)
 2398 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/2:0H
 2404 pi        20   0    8364   3520   2712 S   0.0   0.1   0:00.10 bash

rgaudin commented 2 years ago

OK I eventually could download the image and reproduce the issue (so did @Popolechien).

Indeed, every kiwix-request triggers a spike in mount.exfat's process but the search keeps the process at 99% CPU for what feels like forever. I stopped after 12mn…

While the exact cause of the issue remains unknown, it is linked to the FUSE exfat driver that is being used.

We are not using FUSE exfat on purpose. We needed exfat-utils at some point during setup (which comes with exfat-fuse) and forgot to uninstall it.

Removing exfat-fuse solves the problem. search's speed is now acceptable but it varies a lot based on:

first search request is always slow
speed of microSD (probably has the biggest impact)
requested string. I see the variation but can't figure out the pattern. Maybe @mgautierfr who knows the internals of the xapian index has a better understanding.

Search and browsing have very limited impact on RAM. System is not stressed at all.

We'll prepare another image without exfat-fuse.

Solution

sudo apt remove exfat-fuse ; reboot

kelson42 commented 2 years ago

Closing as there is nothing more to do here.

mgautierfr commented 2 years ago

I see the variation but can't figure out the pattern. Maybe @mgautierfr who knows the internals of the xapian index has a better understanding.

From what I understand, xapian organizes the stored terms be keeping orthographically similar terms (word ~= world) closed in memory. So if you search for a term ("apple") xapian will load the memory around the "a", "ap", "app", "appl", "apple" terms. They are all located in the same region, so there is a lot of change the information is already loaded. But if you start to searching for "zoo", xapian have to discard a lot of already loaded info and start again to load new memory region.

kiwix / kiwix-tools

kiwix-serve hangs on search on Pi with SO ZIM #519

Solution