Hey,
yelni...@tutamail.com writes:
> It is still slow on 1.0.3 to do anything once its started but with 1.0.4rc1
> even starting is extremely painful.
> I tried to manually add features to the system-log-service and the
> thing that causes everything to slow down drastically is the addition
> of the #:kernel-log-file (even if it is empty).
>
> Setting that to #f instead makes the test now fail considerable faster (1.8s
> rather than 900).
Interesting.
I cross-compiled current ‘main’ to test it in my childhurd, as an
unprivileged user, like so:
echo '(use-modules (shepherd service system-log)) (register-services (list
(system-log-service (list (endpoint (make-socket-address AF_UNIX
"/home/ludo/syslog.sock") #:style SOCK_DGRAM)) #:kernel-log-file "t.conf")))' >
t.conf
./shep/bin/shepherd -c t.conf &
I can reproduce the unresponsiveness as soon as I run ‘herd start
system-log’.
Unfortunately, rpctrace is unhelpful. Even ‘rpctrace -o log
./shep/bin/shepherd --version’ hangs:
--8<---------------cut here---------------start------------->8---
ludo@childhurd ~$ rpctrace -s 10 -o log ./shep/bin/shepherd --version
Terminated
ludo@childhurd ~$ tail -50 log ; echo END
task13(pid283)-> 3206 (pn{ 35}) = 0
78<--79(pid283)->io_map_request () = 0 80<--77(pid283) (null)
task13(pid283)-> 2089 (48619520 4096 0 0 80<--77(pid283) 4096 1 5 7 1) = 0x3
((os/kern) no space available)
task13(pid283)-> 2023 (48619520 4096) = 0
task13(pid283)-> 2089 (48619520 4096 0 0 80<--77(pid283) 4096 1 5 7 1) = 0
48619520
task13(pid283)-> 3206 (pn{ 35}) = 0
78<--79(pid283)->io_map_request () = 0 80<--81(pid283) (null)
task13(pid283)-> 2089 (48623616 4096 0 0 80<--81(pid283) 8192 1 1 7 1) = 0x3
((os/kern) no space available)
task13(pid283)-> 2023 (48623616 4096) = 0
task13(pid283)-> 2089 (48623616 4096 0 0 80<--81(pid283) 8192 1 1 7 1) = 0
48623616
task13(pid283)-> 3206 (pn{ 35}) = 0
78<--79(pid283)->io_map_request () = 0 80<--77(pid283) (null)
task13(pid283)-> 2089 (48627712 4096 0 0 80<--77(pid283) 8192 1 3 7 1) = 0x3
((os/kern) no space available)
task13(pid283)-> 2023 (48627712 4096) = 0
task13(pid283)-> 2089 (48627712 4096 0 0 80<--77(pid283) 8192 1 3 7 1) = 0
48627712
task13(pid283)-> 3206 (pn{ 35}) = 0
task13(pid283)-> 3206 (pn{ 34}) = 0
17<--33(pid283)->dir_lookup ("gnu/store/" 4194305 0) = 0 1 ""
78<--81(pid283)
78<--81(pid283)->term_getctty () = 0xfffffed1 ((ipc/mig) bad request message
ID)
78<--81(pid283)->io_read_request (-1 512) = 0 "\x7fELF\x01\x01\x01\0\0\0"
78<--81(pid283)->io_stat_request () = 0 {23 7 0 80111 0 1744699086 0 33133 1
0 0 375340 0 1744691226 270000000 1 0 1744691169 440000000 8192 744 0 0 0 0 0 0
0 0 0 0 0}
78<--81(pid283)->io_map_request () = 0 80<--79(pid283) (null)
task13(pid283)-> 2089 (0 379380 0 1 80<--79(pid283) 0 1 1 7 1) = 0 48631808
task13(pid283)-> 3206 (pn{ 35}) = 0
78<--81(pid283)->io_map_request () = 0 80<--77(pid283) (null)
task13(pid283)-> 2089 (48676864 204800 0 0 80<--77(pid283) 45056 1 5 7 1) =
0x3 ((os/kern) no space available)
task13(pid283)-> 2023 (48676864 204800) = 0
task13(pid283)-> 2089 (48676864 204800 0 0 80<--77(pid283) 45056 1 5 7 1) =
0 48676864
task13(pid283)-> 3206 (pn{ 35}) = 0
78<--81(pid283)->io_map_request () = 0 80<--79(pid283) (null)
task13(pid283)-> 2089 (48881664 122880 0 0 80<--79(pid283) 249856 1 1 7 1) =
0x3 ((os/kern) no space available)
task13(pid283)-> 2023 (48881664 122880) = 0
task13(pid283)-> 2089 (48881664 122880 0 0 80<--79(pid283) 249856 1 1 7 1) =
0 48881664
task13(pid283)-> 3206 (pn{ 35}) = 0
78<--81(pid283)->io_map_request () = 0 80<--77(pid283) (null)
task13(pid283)-> 2089 (49004544 8192 0 0 80<--77(pid283) 368640 1 3 7 1) =
0x3 ((os/kern) no space available)
task13(pid283)-> 2023 (49004544 8192) = 0
task13(pid283)-> 2089 (49004544 8192 0 0 80<--77(pid283) 368640 1 3 7 1) = 0
49004544
task13(pid283)-> 3206 (pn{ 35}) = 0
task13(pid283)-> 3206 (pn{ 34}) = 0
task13(pid283)-> 2089 (48435200 65536 0 0 (null) 0 1 3 7 1) = 0x3 ((os/kern)
no space available)
task13(pid283)-> 2089 (48435200 65536 0 1 (null) 0 1 3 7 1) = 0 49012736
task13(pid283)-> 2012 (1 22) = 0 {0 25 183304192 6975488 0 0 0 0 1744693029
80000 0 0 0 0 0 0 0 0 1744693029 0 80000000 0}
task13(pid283)-> 2012 (3 12) = 0 {0 0 0 10000 0 0 0 0 0 0 10000000 0}
task13(pid283)-> 2012 (1 22) = 0 {0 25 183304192 6975488 0 0 0 0 1744693029
80000 0 0 0 0 0 0 0 0 1744693029 0 80000000 0}
task13(pid283)-> 2012 (3 12) = 0 {0 0 0 10000 0 0 0 0 0 0 10000000 0}
65<--64(pid283)->io_write_request ("\0" -1) = 0 1
18... = 0 "\0"
task13(pid283)-> 2089 (49078272 471040 0 0 (null) 0 1 3 7 1) ...18
task13(pid283)-> 4204 (18820768 2 0 0 0)END
--8<---------------cut here---------------end--------------->8---
> Running the logger manually only the syslog_remote_file seems to be created.
> This is consistent with the log output from the test.
> I also added a pk for the message-sender to investigate.
> Difference I can see is that on Linux most of them are #f but here are #(1
> \x00") instead
Yeah that’s the data coming from ‘recvfrom!’ where 1 = AF_UNIX and Linux
returns nothing.
Thanks,
Ludo’.
