Re: [PATCH 0/4 V7] MI notification on trace started/stopped

[Pedro Alves <palves at redhat dot com>]

On 12/19/2013 06:48 AM, Yao Qi wrote:
> Pedro,
> Thanks for giving such great example to facilitate the discussion.
> 
> On 12/18/2013 10:09 PM, Pedro Alves wrote:
>> With trace events sent on a separate channel, we can get things
>> like this, with a single-threaded program being traced:
>>
>>  #1 - tstart, resume program
>>  #2 - trace stops because buffer full
>>  #3 - gdbserver queues trace stop notification.
> 
> Unlike stop notification, trace status notification is unlikely to be
> queued in GDBserver.  Multiple threads may trigger multiple stops, and
> stop notifications can be queued in GDBserver.  However, trace status
> is a global state in GDBserver.  When tracing is stopped, trace status
> can't be changed until GDB requests some changes.  That is to say,
> GDBserver shouldn't get a new trace stop notification before the last
> one is ack'ed by GDB.

I didn't mean queued behind another _trace_ event.  I meant queued
behind _other_ events GDB is handling.  Like, gdb handling the %Stop
or stdin before the %Trace.  Events on the GDB side are
ultimately handled serially.  So GDB can handle both stdin and
stop events before the trace event is handled.

Actually, we don't need stop events to show the problem.
async/non-stop/stdin work just as well:

#1 - (gdb) tstart
#2 - (gdb) c -a &
#3 - User types "tstop/tstart" (or runs a user defined command
     that does both with one command).
#4 - Meanwhile, as GDB is processing the "stdin" events, the
     trace stops on target, and a trace event is sent down the
     wire.  Let's say this event now "queued"
     until it is processed by GDB's event loop.
#5 - Due to #3, GDB outputs MI =trace-stop, followed by =trace-start.
#6 - The RSP trace-stop event is finally handled, and GDB outputs
     MI =trace-stop.
#7 - The frontend is now out of sync, because the the trace is actually
     running.

This is actually very much like GDB needing to be sure the frontend
doesn't get out of sync, with MI *running and *stopped
events/notifications.

> 
> If target is able to trigger trace start, trace notification may be
> queued, like this sequence,
> 
>  #1 GDBserver sends %Trace on trace start, triggered by target,
>  #2 trace stops because buffer full
>  #3 gdbserver queues %Trace on trace stop (because notification in #1
>     has not been ack'ed)
> 
> That is the _only_ case I can think of.
> 
>>  #4 - breakpoint at "next_session" is hit.
>>  #5 - gdb happens to process breakpoint notification first.
>>  #6 - The "next_session" breakpoint has a breakpoint
>>       command that does: "tstop; tsave; tstart; continue"
>>       (program iterates, and another collection sample begins)
>>  #7 - GDB emits MI =trace-stopped then =trace-started in response
>>       to tstop/tstart above.
>>  #8 - gdb processes the pending trace stop notification, emits
>>       MI =trace-stopped to frontend.
>>  #9 - The frontend is confused, thinking the trace session is
>>       stopped, when it is in fact running.
>>
>> Now, even if we sent trace stops down the %Stop
>> notification, that wouldn't happen.  GDB would always process
>> the trace stop notification before the breakpoint.
> 
> Sorry, it is unclear to me.  What do you mean by "send trace stops down
> the %Stop"?  Using %Stop to send trace stop notification?

Yes.  Sorry, the "even" shouldn't be there.  I meant:

"Now, if we sent trace stops down as a %Stop notification, that
wouldn't happen.  GDB would always process the trace stop
notification before the breakpoint."  But as both the
multi-threaded and the stdin examples show, that's not sufficient.

> 
>>
>> But, considering multi-threaded programs, a different thread
>> can stop the trace immediately after the breakpoint at
>> next_session hits and triggers a %Stop notification,
>> and so sending trace notifications using %Stop wouldn't
>> fix the frontend confusion in this case, as the stop would
>> still be processed before the trace stop.
>>
>> What I'm just now thinking would fix it would be if the
>> remote _also_ triggered trace _start_ notifications in
>> addition to trace stops:
>>
>>  #1 - tstart, resume program
>>  #2 - trace stops because buffer full
>>  #3 - gdbserver queues trace stop notification.
>>  #4 - breakpoint at "next_session" is hit.
>>  #5 - gdb happens to process breakpoint notification first.
>>  #6 - The "next_session" breakpoint has a breakpoint
>>       command that does: "tstop; tsave; tstart; continue"
>>       (program iterates, and another collection sample begins)
>>  #7 - GDB emits MI =trace-stopped then =trace-started in response
>>       to tstop/tstart above.
>>  #8 - gdb processes the pending trace stop notification, emits
>>       MI =trace-stopped to frontend.
>>  #9 - gdb processes a trace start notification, emits
>>       MI =trace-start to frontend.
>>  #10 - frontend displays the trace session as running.
>>
> 
> In order to get the queued trace notification, these steps can be
> revised a little,
> 
>  #1 - trace is not started,
>  #2 - trace is started triggered by target, %Trace is sent
>  #3 - one thread hits breakpoint at "next_session", %Stop is sent
>  #4 - the other thread triggers trace stops because buffer full,
>  #5 - gdbserver queues trace stop notification (because notification in
>       #2 hasn't been ack'ed),
> 
> When GDB starts process notification, GDB will process two %Trace first
> (#2 and #4), then it processes %Stop, because in notif_queue, different
> type of notifications are processed in an FIFO order.  In notif_queue,
> we have Trace (1), Stop, Trace (2), but they are processed in this
> order: Trace (1), Trace (2), Stop.
> 
> MI notifications are correct to MI front-end.
> 
> The follow steps really trigger the problem:
> 
>  #1 - thread A hit breakpoint, %Stop is send,
>  #2 - trace is started triggered by target, %Trace is sent
>  #3 - one thread hits breakpoint at "next_session", stop notification
>       is queued in GDBserver,
>  #4 - the other thread triggers trace stops because buffer full, trace
>       notification is queued too.
> 
> In notif_queue, we have Stop (1), Trace (1), Stop (2), Trace (2), and
> they are processed in order: Stop (1), Stop (2), Trace (1), Trace (2).
> Then, MI notification are incorrect to MI front-end.
> 
>> To fully fix that, MI trace events triggered
>> by GDB actions could be distinguishable from MI trace
>> events triggered by the target (e.g, an attribute),
>> and the frontend could only look at target-triggered
>> events.  I'm not sure that's really necessary, and it can
>> always be added later, but it may be nice to have.
>>
>> Another way to fix the ordering issue I just thought would
>> be to have a sequence number associated with each trace
>> session, and send those along trace start/stop notifications,
>> so that a delayed =trace-stopped generated from the target
>> would be older than the current trace session, so
>> it would be ignored.  Not sure how I feel about that.
>> Not sure how I feel about the other solution either.  
>>
>> Seems to me something needs to be done though.
> 
> These two solutions require MI front-end to have some extra logic
> handling this ordering issue.  

I was thinking that GDB would handle the sequence number
filtering on its own (the frontend wouldn't see them), but
I haven't thought that through.

> How about triggering MI trace events
> _only_ by %Trace notification?  Even tracing is started or stopped
> by commands in CLI, GDBserver still emits %Trace for started or stopped
> trace.  In this way, the ordering issue can be resolved.

Hmm.  I realized one more point to add to the discussion.

What GDB makes to sure the frontend doesn't get out
of sync wrt to thread's running state is that stops requests
are asynchronous, so GDB emits *running on its own (not when
the target said the resumption is effective), but *stopped is
only emitted when the target really reports it stopped,
not when the stop is requested with vCont;t.

But, unlike "vCont;t", tstop/QTStop requests are synchronous.
That is, when the target replies OK, the trace is stopped,
period.  It then worries me that the %Trace event will only
came later, after the "tstop" command returns.  Hmm^2.
So maybe we need to make sure that %Trace stop events
are flushed/consumed on "tstop"?
But If we'll ever support traces starting on their own on
the target, that may add to the complication.  I haven't
thought this part through, and I have to leave now for a
bit, but I thought I'd send out the email now anyway.

-- 
Pedro Alves