[9fans] interleaved output of ratrace

[9fans] interleaved output of ratrace

[Nick Owens]

[-- Attachment #1: Type: text/plain, Size: 600 bytes --]

hello,

i'm trying to use ratrace to debug a go binary.
what i don't understand is why records of syscalls sometimes appear on
top of one another.

here's the output of 'ratrace -c ./strings.test >[2]/tmp/ratrace.log',
where strings.test is made with 'go test -c strings'.

http://sprunge.us/aCBG

you can see in several places that more than one syscall record is
printed on the same line.

i find this quite odd since in /sys/src/cmd/ratrace.c:/^writer all
output comes from a channel.

i'm running this on 9front/amd64, but i'd appreciate if anyone can test
on other systems.


[-- Attachment #2: Type: application/pgp-signature, Size: 836 bytes --]

Re: [9fans] interleaved output of ratrace

[Bakul Shah]

On Mon, 21 Jul 2014 17:41:17 PDT Nick Owens <mischief@9.offblast.org> wrote:
>
> hello,
>
> i'm trying to use ratrace to debug a go binary.
> what i don't understand is why records of syscalls sometimes appear on
> top of one another.
>
> here's the output of 'ratrace -c ./strings.test >[2]/tmp/ratrace.log',
> where strings.test is made with 'go test -c strings'.
>
> http://sprunge.us/aCBG
>
> you can see in several places that more than one syscall record is
> printed on the same line.

Look at code bracketed by
        if(up->procctl == Proc_tracesyscall){
in /sys/src/9/pc/trap.c

Hints: rfork() returns twice: in parent and in child.  exist()
never returns.  A syscall may finish *after* a later syscall
(from another process) returns.

Re: [9fans] interleaved output of ratrace

[Nick Owens]

[-- Attachment #1: Type: text/plain, Size: 2993 bytes --]

it's all clear now. thanks.

i made my own modifications to syscallfmt.c and ratrace.c, so that pid
textname and syscallname are printed with every call/ret. also call/ret
are always on their own line.

so i can see this now:

175131 strings.test Tsemacquire  = 0 "" 1406064623620695405 1406064683623421761
175131 strings.test Semrelease 22df29 0x88602b8 1
175131 strings.test Semrelease  = 1 "" 1406064683623547693 1406064683623548680
175126 strings.test Semacquire  = 1 "" 1406064623632046760 1406064683623658045
175131 strings.test Semrelease 22df29 0x88610b8 1
175131 strings.test Semrelease  = 1 "" 1406064683623727335 1406064683623728157
175131 strings.test Semacquire 22dec9 0x8860d38 1
177444 strings.test Semacquire  = 1 "" 1406064623620977981 1406064683623757562
175126 strings.test Sleep 22deb2 1
177444 strings.test Semrelease 22df29 0x8860d38 1
177444 strings.test Semrelease  = 1 "" 1406064683624037504 1406064683624038190
175131 strings.test Semacquire  = 1 "" 1406064683623812508 1406064683624112483
177444 strings.test Semacquire 22dec9 0x88610b8 1
175131 strings.test Semrelease 22df29 0x88610b8 1
175131 strings.test Semrelease  = 1 "" 1406064683624200661 1406064683624201290
177444 strings.test Semacquire  = 1 "" 1406064683624192665 1406064683624219267
177444 strings.test Semacquire 22dec9 0x88610b8 1
175131 strings.test Tsemacquire 22dee2 0x8860d38 60000
175126 strings.test Sleep  = 0 "" 1406064683623801874 1406064683634370193
175126 strings.test Semacquire 22dec9 0x88602b8 1

instead of this madness

44252 strings.test Sleep 22deb2 144250 strings.test Semrelease 22df29 0x8860d38 1 = 1 "" 1406056428269692341 1406056428269693353
44250 strings.test Semacquire 22dec9 0x61b838 1 = 1 "" 1406056428247491710 1406056428269742554
44256 strings.test Semrelease 22df29 0x61b838 1 = 1 "" 1406056428269726447 1406056428269802399
 = 1 "" 1406056428269795670 1406056428269796415
44256 strings.test Semacquire 22dec9 0x8860d38 1 = 0 "" 1406056428269665424 1406056428282146209
44252 strings.test _nsec 22def9 0x7ffffeffee98 = 0 "" 1406056428282219249 1406056428282219729
44252 strings.test Sleep 22deb2 1 = 0 "" 1406056428282268622 1406056428292646883
44252 strings.test _nsec 22def9 0x7ffffeffee98 = 0 "" 1406056428292698619 1406056428292699234
44250 strings.test Semrelease 22df29 0x8860d38 144252 strings.test Sleep 22deb2 1 = 1 "" 1406056428292767078 1406056428292767798
 = 1 "" 1406056428274879925 1406056428292782567
44256 strings.test Semrelease 22df29 0x61b838 1 = 1 "" 1406056428292856057 1406056428292856451
44250 strings.test Semacquire 22dec9 0x61b838 144256 strings.test Semacquire 22dec9 0x8860d38 1 = 1 "" 1406056428292891465 1406056428292891895
 = 0 "" 1406056428292758927 1406056428303195365
44252 strings.test _nsec 22def9 0x7ffffeffee98 = 0 "" 1406056428303252044 1406056428303252502
44252 strings.test Sleep 22deb2 144250 strings.test _nsec 22def9 0x7ffffeffed20 = 0 "" 1406056428308625883 1406056428308626351


[-- Attachment #2: Type: application/pgp-signature, Size: 836 bytes --]

Re: [9fans] interleaved output of ratrace

[cinap_lenrek]

fixed.

--
cinap