[linux] strace -o bestand programma, analize

[Geert Stappers]

In-Reply-To: <20201209195111.GA4530 op bakunin.xs4all.nl>
On Wed, Dec 09, 2020 at 08:51:11PM +0100, Daniel C. von Asmuth wrote:
> Aldus schreef Paul Slootman op Fri, Dec 04, 2020 at 05:53:07PM +0100:
> > On Fri 04 Dec 2020, Daniel C. von Asmuth wrote:
> > 
> > > > >> > > > > Een manier om zoiets te onderzoeken is met het volgende commando:
> > > > >> > > > >
> > > > >> > > > >         strace -T -o trace.txt vlc
> > 
> > Ik zou er -f bijzetten, dan zie je ook alle threads en evt. geforkte
> > processen.
>  	[...]
> 
> > Hoogstewaarschijnlijk omdat een andere thread iets aan het doen is, wat
> > weten we nu niet. Daar worden zulke futex'en ook voor gebruikt: om
> > threads te synchroniseren.
> 
> Bedankt. Ik heb wat huiswerk gedaan met Harry's strace file:
> 
> 	[...]
> 14031 clone(child_stack=0x7fd26a098f30, flags=CLONE_VM|CLONE_FS|CLONE_FILES|
>       CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|
>       CLONE_CHILD_CLEARTID, parent_tid=[14035], tls=0x7fd26a099700, 
>       child_tidptr=0x7fd26a0999d0) = 14035 <0.000056>
> 14035 set_robust_list(0x7fd26a0999e0, 24 <unfinished ...>
> 14035 <... set_robust_list resumed>)    = 0 <0.000014>
> 14035 futex(0x5608dbe55f98, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
> 14031 futex(0x5608dbe55f98, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000006>
> 14035 <... futex resumed>)              = 0 <26.026223>
> 14035 gettid( <unfinished ...>
> 14035 <... gettid resumed>)             = 14035 <0.000012>
> 14035 write(2, "[\33[32;1m00005608dbe55e50\33[0m] ", 30 <unfinished ...>
> 14035 <... write resumed>)              = 30 <0.000008>
> 14035 write(2, "main playlist: \33[0;1m", 21) = 21 <0.000006>
> 14035 write(2, "playlist is empty", 17) = 17 <0.000005>
> 14035 write(2, "\33[0m\n", 5 <unfinished ...>
> 14035 <... write resumed>)              = 5 <0.000008>
> 14035 futex(0x5608dbe55f48, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
> 14035 <... futex resumed>)              = 0 <0.000021>
> 14035 futex(0x5608dbe55f9c, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
> 14035 <... futex resumed>)              = 0 <188.225758>
> 14035 futex(0x5608dbe55f48, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
> 14035 <... futex resumed>)              = 0 <0.000266>
> 14035 openat(AT_FDCWD, "/sys/devices/system/cpu/online", O_RDONLY|O_CLOEXEC <unfinished ...>
> 14035 <... openat resumed>)             = 31 <0.000020>
> 14035 read(31, "0-5\n", 8192)           = 4 <0.000015>
> 14035 close(31 <unfinished ...>
> 14035 <... close resumed>)              = 0 <0.000008>
> 	[...] 
> 
> Dit laat zien hoe het hoofdprogramma 14031 vlak na het opstarten een 
> nieuwe thread 14035 maakt, die vervolgens wacht op futex 0x5608dbe55f98 
> en pas na 26 seconden weer wakker wordt gekust door het hoofdprogramma 
> om daarna de tekst "main playlist: playlist is empty" naar het scherm 
> te schrijven en verder te gaan.... Veel wijzer word ik er ook niet van. 
> Daar heb je de broncode voor nodig...

Er is een tussenvorm:  debug-versie, danwel een ongestripte versie.
(strippen van labels  (niet van kledingstukken))
En is iets voor een eventueele volgende thread

 
> Voor de volledigheid: ik gebruikte de volgende commando's:
> 
> rev trace.txt >out1

Achterste voren


> cut -f 1 -d ' ' out1 >out2

Bewaar wat voor de eerste spatie staat


> rev out2 >out3

Dat weer achterste voren


> tr -d '<>' <out3 >out4

Gooi de vishaken weg


> paste out4 trace.txt >out5

Voeg samen


> sort -n out5 >out6

Sorteer nummeriek


> tail out6

Laat de staart zien


 
> Dan zie je waar de grootste wachttijden waren. 
> 
> Met vriendelijke groet,
> Daniel von Asmuth

Dank voor 'rev' en 'paste' onder de aandacht brengen.


Regards
Geert Stappers
-- 
Silence is hard to parse