[PATCH v5 3/4] Implement -e status=set option

[Paul Chaignon]

On Wed, Jul 03, 2019 at 08:42:41PM +0300, Dmitry V. Levin wrote:
> On Tue, Jul 02, 2019 at 02:26:42PM +0200, Paul Chaignon wrote:
> > On Tue, Jul 02, 2019 at 02:26:44AM +0300, Dmitry V. Levin wrote:
> > > On Fri, Jun 28, 2019 at 11:34:21AM +0200, Paul Chaignon wrote:
> [...]
> > > >  .TP
> > > > +\fB\-e\ status\fR=\,\fIset\fR
> > > > +Trace only system calls with the specified return status.  The default is
> > > > +.BR status = all .
> > > > +When using the
> > > > +.B status
> > > > +qualifier, because
> > > > +.B strace
> > > > +waits for system calls to return before deciding if they should be printed, the
> > > > +order of events may not be preserved anymore.  For example, if a first system
> > > > +call is being executed and another is called by a different thread,
> > > > +.B strace
> > > > +will print the first system call after the second.  The first system call will
> > >
> > > Do you mean that both entering and exiting of another syscall happen after
> > > entering but before exiting of the first syscall?
> > 
> > If that second syscall exits first, yes.  What about the following?
> > 
> >   For example, if two system calls are executed by concurrent threads,
> >   strace will first print both the entry and exit of the first system call
> >   to exit, regardless of their respective entry time.  The entry and exit
> >   of the second system call to exit will be printed afterwards.
> 
> I think it's not correct to say that the order of events is not preserved.
> Traditionally syscalls are printed in the order of syscall entering.
> When status filtering is enabled, they are printed in the order of syscall
> exiting.

I understand what you mean, but I think it would be a bit misleading.
When the man page previously states that "strace will try to preserve the
order of those events," it refers to syscall entries and exits and points
to the following example (in case of interleaved syscalls from multiple
threads):

  [pid 28772] select(4, [3], NULL, NULL, NULL <unfinished ...>
  [pid 28779] clock_gettime(CLOCK_REALTIME, {1130322148, 939977000}) = 0
  [pid 28772] <... select resumed> )      = 1 (in [3])

I've written that it does not preserve the order of events because, with
staged output, select's entry above will appear after clock_gettime's
entry and exit, even though that is not the order in which those events
occurred.

In addition, if we consider that this new order of events is "in the order
of syscall exiting," then I would expect "in the order of syscall
entering" to look like:

  [pid 28772] select(4, [3], NULL, NULL, NULL <unfinished ...>
  [pid 28772] <... select resumed> )      = 1 (in [3])
  [pid 28779] clock_gettime(CLOCK_REALTIME, {1130322148, 939977000}) = 0

Maybe we should add this example to the man page, so that the expected
behavior is clear to the user, regardless of what we call it?

Paul