High CPU usage during startup

[zqhong]

Basic Information:

Firefox: v101.0.1-r0
Docker Image: v22.10.3
OS: Rocky Linux release 9.0 (Blue Onyx)
Docker: 20.10.20

My docker start command:

docker run -d \
    --name=docker-firefox \
    -p 5800:5800 \
    -v /docker/appdata/firefox:/config:rw \
    -e "VNC_PASSWORD=***"  \
    --shm-size 1g \
    jlesage/firefox

Firefox log:

==> /docker/appdata/firefox/log/firefox/error.log <==

###!!! [Child][PContentChild] Error: Send(msgname=PContent::Msg_ScriptErrorWithStack) Channel closing: too late to send/recv, messages will be lost

###!!! [Child][PContentChild] Error: Send(msgname=PContent::Msg_ScriptErrorWithStack) Channel closing: too late to send/recv, messages will be lost

###!!! [Child][PContentChild] Error: Send(msgname=PContent::Msg_ScriptErrorWithStack) Channel closing: too late to send/recv, messages will be lost

Missing chrome or resource URL: resource://gre/modules/UpdateListener.jsm

==> /docker/appdata/firefox/log/firefox/output.log <==
Crash Annotation GraphicsCriticalError: |[0][GFX1-]: glxtest: libpci missing (t=238.873) |[1][GFX1-]: glxtest: libEGL missing (t=238.874) |[2][GFX1-]: glxtest: libGL.so.1 missing (t=238.874) |[3][GFX1-]: glxtest: libEGL missing (t=238.874) |[4][GFX1-]: No GPUs detected via PCI (t=238.874) [GFX1-]: No GPUs detected via PCI

Information obtained by strace -p [pid]:

18:53:05 close(454214)                  = -1 EBADF (Bad file descriptor) <0.000011>
18:53:05 close(454215)                  = -1 EBADF (Bad file descriptor) <0.000005>
18:53:05 close(454216)                  = -1 EBADF (Bad file descriptor) <0.000005>
18:53:05 close(454217)                  = -1 EBADF (Bad file descriptor) <0.000005>
18:53:05 close(454218)                  = -1 EBADF (Bad file descriptor) <0.000007>
18:53:05 close(454219)                  = -1 EBADF (Bad file descriptor) <0.000005>
18:53:05 close(454220)                  = -1 EBADF (Bad file descriptor) <0.000005>
18:53:05 close(454221)                  = -1 EBADF (Bad file descriptor) <0.000005>
18:53:05 close(454222)                  = -1 EBADF (Bad file descriptor) <0.000005>
18:53:05 close(454223)                  = -1 EBADF (Bad file descriptor) <0.000005> 

[jlesage]

Once started, is the container still usage a lot of CPU ? It normal for the container to consume more CPU during startup...

[zqhong]

thank you for your reply. CPU usage is normal after startup.

It's just that I look at the strace log, a lot of Bad file descriptor is not normal in my opinion.

[zqhong]

extra information:

#  strace -Tt -p [pid]
11:16:01 open("/etc/machine-id", O_RDONLY|O_LARGEFILE) = 10 <0.000038>
11:16:01 fstat(10, {st_mode=S_IFREG|0644, st_size=33, ...}) = 0 <0.000006>
11:16:01 read(10, "3e0a555284ac4f2ebe42c5c279d07637"..., 33) = 33 <0.000012>
11:16:01 close(10)                      = 0 <0.000009>

11:16:01 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000006>
11:16:01 pipe([10, 11])                 = 0 <0.000015>
11:16:01 pipe([12, 13])                 = 0 <0.000012>
11:16:01 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [CHLD], 8) = 0 <0.000010>
11:16:01 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0 <0.000008>
11:16:01 fork()                         = 529 <0.000654>
11:16:01 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0 <0.000007>
11:16:01 rt_sigprocmask(SIG_SETMASK, [CHLD], NULL, 8) = 0 <0.000006>
11:16:01 close(11)                      = 0 <0.000006>
11:16:01 close(13)                      = 0 <0.000007>

# Note: a lot of time is spent here
11:16:01 read(10, "", 1024)             = 0 <203.380721>
11:19:25 wait4(529, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], 0, NULL) = 529 <0.000119>

11:19:25 read(12, "", 1024)             = 0 <0.000010>
11:19:25 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000006>
11:19:25 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=529, si_uid=1000, si_status=1, si_utime=5900, si_stime=13938} ---
11:19:25 close(10)                      = 0 <0.000013>
11:19:25 close(12)                      = 0 <0.000008>
11:19:25 stat("/config/profile", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000011>
11:19:25 stat("/config/profile/.parentlock", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000008>
11:19:25 open("/config/profile/.parentlock", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 10 <0.000033>
11:19:25 fcntl(10, F_GETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0, l_pid=1566065899}) = 0 <0.000007>
11:19:25 fcntl(10, F_SETLK, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000007>

As you can see(11:16:01 read(10, "", 1024) = 0 <203.380721>), there is a read function that took 203 seconds.

[jlesage]

I assume the PID you are talking about is the one of Firefox ?

Note that this project is only packaging Firefox into a Docker container. I don't modify, adjust or fix the source code. If you think there is a problem with Firefox itself, you are probably better to report it directly to Mozilla. Also, you should be able to see the same behaviour with a "normal" Linux installation.