From mboxrd@z Thu Jan  1 00:00:00 1970
To: Fans of the OS Plan 9 from Bell Labs <9fans@9fans.net>
In-reply-to: Your message of "Mon, 21 Jul 2014 17:41:17 PDT."
	<20140722004117.GE31918@iota.offblast.org>
References: <20140722004117.GE31918@iota.offblast.org>
Date: Tue, 22 Jul 2014 10:06:30 -0700
From: Bakul Shah <bakul@bitblocks.com>
Message-Id: <20140722170630.A0335B82A@mail.bitblocks.com>
Subject: Re: [9fans] interleaved output of ratrace
Topicbox-Message-UUID: 085ec948-ead9-11e9-9d60-3106f5b1d025

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.