[linux] strace -o bestand programma

Vr Dec 4 14:17:05 CET 2020

Aldus schreef harry.harmsen op gmail.com op Thu, Dec 03, 2020 at 08:06:24PM +0100:
> Op wo 2 dec. 2020 om 23:52 schreef <harry.harmsen op gmail.com>:
> > Op wo 2 dec. 2020 om 19:06 schreef Geert Stappers <stappers op stappers.nl>:
> >> On Wed, Dec 02, 2020 at 07:03:13PM +0100, harry.harmsen op gmail.com wrote:
> >> > Op wo 2 dec. 2020 om 18:40 schreef Geert Stappers <stappers op stappers.nl
> >> > > On Wed, Dec 02, 2020 at 05:52:47PM +0100, harry.harmsen op gmail.com
> >> > > > Op ma 30 nov. 2020 om 22:22 schreef Daniel C. von Asmuth:
> >> > >        ....
> >> > > > >
> >> > > > > Een manier om zoiets te onderzoeken is met het volgende commando:
> >> > > > >
> >> > > > >         strace -T -o trace.txt vlc
> >> > > > >
> >> > > > >         man strace
> >> > >   ...
> >> > > > Een klein half uurtje geleden gaf ik in de terminal het door jou
> >> > > > aangegeven commando .
> >> > > > Dit is tot op heden de output:
> >> > > >
> >> > > > harry op harry-System:~$ strace -T -o trace.txt vlc
> >>          ...
> >> > > >
> >> > > > En verder blijft de cursor in de terminal knipperen.
> >> > > > Lijkt me niet de door jou bedoelde output.
> >> > > > Geen idee wat ik verkeerd doe.
> >> > >
> >> > > Niets verkeerd.
> >> > >
> >> > > Je bent aan het leren dat  -o   iets is als "output moet in"
> >> > >
> >> > > Druk op Control-C, krijgt prompt terug en hebt een (lomp groot??)
> >> > > trace.txt bestand.
> >> >
> >> > Ik weet niet of ik je goed begrijp, maar ik heb in de terminal nogmaals
> >> het
> >> > commando van Daniël gegeven en toen ie een tijdje niks deed Contol-C.
> >> > Dit is het resultaat:
> >> >
> >> > harry op harry-System:~$ strace -T -o trace.txt vlc
> >> > VLC media player 3.0.9.2 Vetinari (revision 3.0.9.2-0-gd4c1aefe4d)
> >> > [000055b9b225c5b0] main libvlc: Vlc draait met de standaardinterface.
> >> > Gebruik 'cvlc' om vlc zonder interface te gebruiken.
> >> > qt5ct: using qt5ct plugin
> >> > qt5ct: D-Bus global menu: no
> >> > qt5ct: D-Bus system tray: yes
> >> > [000055b9b22e9e50] main playlist: playlist is empty
> >> > ^Charry op harry-System:~$
> >> >
> >> > Lijkt nog niet niet op (lomp groot?) trace.txt bestand?
> >>
> >> ls -l trace.txt
> >> ls -hl trace.txt

Zoals ik al suggereerde wil je niet het hele bestand doorlezen - ruim 2000 regels.
Daarom heb ik er een paar uitgeknipt:

clone(child_stack=0x7fbe9980bf30, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tid=[21305], tls=0x7fbe9980c700, child_tidptr=0x7fbe9980c9d0) = 21305 <0.000028>
rt_sigprocmask(SIG_SETMASK, [HUP INT QUIT PIPE TERM CHLD], NULL, 8) = 0 <0.000004>
futex(0x7fbe9c2840a0, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0 <25.521139>
futex(0x560d7c737f98, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000011>
rt_sigprocmask(SIG_SETMASK, [HUP INT QUIT PIPE TERM], NULL, 8) = 0 <0.000022>
rt_sigaction(SIGHUP, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 <0.000060>
rt_sigtimedwait([HUP INT QUIT TERM], {si_signo=SIGINT, si_code=SI_KERNEL}, NULL, 8) = 2 (SIGINT) <152.944456>
rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fbe9f8d2210}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 <0.000037>
rt_sigaction(SIGALRM, {sa_handler=0x560d7c67c980, sa_mask=[ALRM], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fbe9f8d2210}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 <0.000104>
rt_sigprocmask(SIG_UNBLOCK, [INT ALRM], NULL, 8) = 0 <0.000027>
alarm(3)                                = 0 <0.000018>
getpid()                                = 21299 <0.000016>
tgkill(21299, 21299, SIGTERM)           = 0 <0.000019>

In bovenstaande zie je de enige twee system calls die veel tijd kostten. De laatste bijna
153 seconden - ik neem aan dat dat Harry's <Ctrl-C> was (gerekend vanaf het opstarten
van het programma). Het programma stopt niet onmiddellijk, maar sluit daarna snel af.

Daarvoor gebeurt iets verdachts: een futex system call die de aanroepende thread
ruim 25 seconden liet wachten. Het adres 0x7fbe9c2840a0 komt verder nergens in
de trace voor, dus veel wijzer maakt dat ons niet. Het bevestigt in ieder geval
ons vermoeden dat VLC ergens op stond te wachten zonder veel te doen. Futex is
wat in Windows en Unix een Mutex heet en clone() is verwant aan fork(). 

	https://man7.org/linux/man-pages/man2/futex.2.html
	https://man7.org/linux/man-pages/man2/clone.2.html

Vlak daarvoor treffen we een clone() system call aan in de trace file. Dat betekent
dat het programma een extra proces opstart. Als je geïnteresseerd bent in wat dat
proces doet kun je de strace opdracht herhalen met de '-f' optie.

	https://man7.org/linux/man-pages/man1/strace.1.html

Wat ik miste in de beschrijving was of Harry ook een venster zag verschijnen van het
VLC programma....

Kortom: deze actie gaf nog geen uitsluitsel.

Met vriendelijke groet,

Daniel von Asmuth
-- 

		How long it takes to reach your goal
		depends less on your speed than on your direction.