[linux] strace -o bestand programma

[Daniel C. von Asmuth]

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...

Voor de volledigheid: ik gebruikte de volgende commando's:

rev trace.txt >out1
cut -f 1 -d ' ' out1 >out2
rev out2 >out3
tr -d '<>' <out3 >out4
paste out4 trace.txt >out5
sort -n out5 >out6
tail out6

Dan zie je waar de grootste wachttijden waren. 

Met vriendelijke groet,


Daniel von Asmuth

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