Avoid emptry tracing callbacks when possible.

Avoid emptry tracing callbacks when possible.

The current code can end up calling the flush callback with an empty data string, even though there is more data to be processed. This doesn't match the description in the comments and can confuse the receiving code. This Cl fixes that, and also simplifies the code a bit.

BUG=481764
Committed: https://crrev.com/90388fdeec253d178bb69366f6222c71f9cc38a4
Cr-Commit-Position: refs/heads/master@{#334421}

[hubbe, 2015-05-07 00:12:23]

hubbe@chromium.org changed reviewers:
+ kbr@chromium.org, nduca@chromium.org

[Ken Russell (switch to Gerrit), 2015-05-08 01:14:34]

kbr@chromium.org changed reviewers:
+ dsinclair@chromium.org, primiano@chromium.org

[Ken Russell (switch to Gerrit), 2015-05-08 01:14:34]

Thanks for fixing this. LGTM, but I'm not an owner.

[dsinclair, 2015-05-08 13:13:12]

Can you give me a bit more context for this, the description is pretty sparse.
We get a blank response from this? Or a response with a trailing ,?  Do we know
why we get a blank or trailing , back?

[Ken Russell (switch to Gerrit), 2015-05-08 18:54:28]

On 2015/05/08 13:13:12, (OOO until May 19th) dsinclair wrote:
> Can you give me a bit more context for this, the description is pretty sparse.
> We get a blank response from this? Or a response with a trailing ,?  Do we
know
> why we get a blank or trailing , back?

Under just the right conditions the flush_output_callback is called one last
time with an empty string and has_more_events = false. This confuses some
calling code.

Actually, looking at this CL again, I think it has the same problem as the
original code. I'll post a follow-up.

[Ken Russell (switch to Gerrit), 2015-05-08 18:54:34]

https://codereview.chromium.org/1131543003/diff/20001/base/trace_event/trace_...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/1131543003/diff/20001/base/trace_event/trace_...
base/trace_event/trace_event_impl.cc:1772: json_events_str_ptr = new
RefCountedString();
What happens if this is hit during the last iteration of the for loop, and there
are no more chunks? Now it looks to me like this has the same problem as the
previous code.

Maybe this isn't worth fixing, but instead rather should be documented.

[hubbe, 2015-05-08 18:58:14]

https://codereview.chromium.org/1131543003/diff/20001/base/trace_event/trace_...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/1131543003/diff/20001/base/trace_event/trace_...
base/trace_event/trace_event_impl.cc:1772: json_events_str_ptr = new
RefCountedString();
On 2015/05/08 18:54:34, Ken Russell wrote:
> What happens if this is hit during the last iteration of the for loop, and
there
> are no more chunks? Now it looks to me like this has the same problem as the
> previous code.
> 
> Maybe this isn't worth fixing, but instead rather should be documented.

This flush happens before appending the current event to the string, so there
will always be at least one more event after this flush.

[hubbe, 2015-05-12 17:17:48]

On 2015/05/08 18:58:14, hubbe wrote:
>
https://codereview.chromium.org/1131543003/diff/20001/base/trace_event/trace_...
> File base/trace_event/trace_event_impl.cc (right):
> 
>
https://codereview.chromium.org/1131543003/diff/20001/base/trace_event/trace_...
> base/trace_event/trace_event_impl.cc:1772: json_events_str_ptr = new
> RefCountedString();
> On 2015/05/08 18:54:34, Ken Russell wrote:
> > What happens if this is hit during the last iteration of the for loop, and
> there
> > are no more chunks? Now it looks to me like this has the same problem as the
> > previous code.
> > 
> > Maybe this isn't worth fixing, but instead rather should be documented.
> 
> This flush happens before appending the current event to the string, so there
> will always be at least one more event after this flush.

Ping?

[nduca, 2015-05-15 18:41:44]

seems like a unit test would be nice....

[hubbe, 2015-05-18 21:51:52]

On 2015/05/15 18:41:44, nduca wrote:
> seems like a unit test would be nice....

Test added.

[dsinclair, 2015-05-25 13:51:11]

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
File base/trace_event/trace_event_unittest.cc (right):

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
base/trace_event/trace_event_unittest.cc:1116: 
This test is .... complicated. Can we simplify it? What, exactly, is it trying
to test?

[hubbe, 2015-06-10 21:55:32]

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
File base/trace_event/trace_event_unittest.cc (right):

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
base/trace_event/trace_event_unittest.cc:1116: 
On 2015/05/25 13:51:11, dsinclair wrote:
> This test is .... complicated. Can we simplify it? What, exactly, is it trying
> to test?

It's trying to make sure that we don't create an empty callback right when we go
from N bytes to N+1 bytes of callback data. Unfortunately N is unknown....

[dsinclair, 2015-06-11 13:54:39]

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
base/trace_event/trace_event_impl.cc:1779:
flush_output_callback.Run(json_events_str_ptr, false);
Doesn't this new code do the same as the old code?

If logged_events->NextChunk returns nullptr then we will flush_output_callback
with an empty json_events_str_ptr and false which was the same problem as
previously, no?

[hubbe, 2015-06-11 17:30:01]

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
base/trace_event/trace_event_impl.cc:1779:
flush_output_callback.Run(json_events_str_ptr, false);
On 2015/06/11 13:54:39, dsinclair wrote:
> Doesn't this new code do the same as the old code?
> 
> If logged_events->NextChunk returns nullptr then we will flush_output_callback
> with an empty json_events_str_ptr and false which was the same problem as
> previously, no?

The new code will only create an empty callback if there is no data at all,
which is consistent with the comment. The existing code can produce callbacks
like:

   DATA, true
   EMPTY, true
   DATA, true
   DATA, false

The comment doesn't explicitly say that won't happen, but it was not what I
expected, which is why the test broke.

[dsinclair, 2015-06-11 19:19:29]

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
base/trace_event/trace_event_impl.cc:1779:
flush_output_callback.Run(json_events_str_ptr, false);
On 2015/06/11 17:30:01, hubbe wrote:
> On 2015/06/11 13:54:39, dsinclair wrote:
> > Doesn't this new code do the same as the old code?
> > 
> > If logged_events->NextChunk returns nullptr then we will
flush_output_callback
> > with an empty json_events_str_ptr and false which was the same problem as
> > previously, no?
> 
> The new code will only create an empty callback if there is no data at all,
> which is consistent with the comment. The existing code can produce callbacks
> like:
> 
>    DATA, true
>    EMPTY, true
>    DATA, true
>    DATA, false
> 
> The comment doesn't explicitly say that won't happen, but it was not what I
> expected, which is why the test broke.
> 
> 


Right, but I don't see how the old code could produce the EMPTY, true case with
more data afterwards? The inner while should keep us looping through the chunks
until either our buffer is full or we've processed them all. How do we end up
breaking out of the while when there are more chunks (in order for
has_more_events to be true) and we also haven't got size() > 
kTraceEventBufferSizeInBytes?

[hubbe, 2015-06-11 21:39:58]

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
base/trace_event/trace_event_impl.cc:1779:
flush_output_callback.Run(json_events_str_ptr, false);
On 2015/06/11 19:19:29, dsinclair wrote:
> On 2015/06/11 17:30:01, hubbe wrote:
> > On 2015/06/11 13:54:39, dsinclair wrote:
> > > Doesn't this new code do the same as the old code?
> > > 
> > > If logged_events->NextChunk returns nullptr then we will
> flush_output_callback
> > > with an empty json_events_str_ptr and false which was the same problem as
> > > previously, no?
> > 
> > The new code will only create an empty callback if there is no data at all,
> > which is consistent with the comment. The existing code can produce
callbacks
> > like:
> > 
> >    DATA, true
> >    EMPTY, true
> >    DATA, true
> >    DATA, false
> > 
> > The comment doesn't explicitly say that won't happen, but it was not what I
> > expected, which is why the test broke.
> > 
> > 
> 
> 
> Right, but I don't see how the old code could produce the EMPTY, true case
with
> more data afterwards? The inner while should keep us looping through the
chunks
> until either our buffer is full or we've processed them all. How do we end up
> breaking out of the while when there are more chunks (in order for
> has_more_events to be true) and we also haven't got size() > 
> kTraceEventBufferSizeInBytes?

Apparently, it's been too long since I thought about this, because my
description of the problem was not accurate. The sequence you get is:

  DATA, true
  ....
  DATA, true
  EMPTY, false

Because at the time we flush one buffer, we don't know that
it's the last one, so has_more_events is still true.

[dsinclair, 2015-06-12 13:48:34]

The CQ bit was checked by dsinclair@chromium.org

[dsinclair, 2015-06-12 13:48:35]

lgtm

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/1131543003/diff/40001/base/trace_event/trace_...
base/trace_event/trace_event_impl.cc:1779:
flush_output_callback.Run(json_events_str_ptr, false);
On 2015/06/11 at 21:39:58, hubbe wrote:
> Apparently, it's been too long since I thought about this, because my
description of the problem was not accurate. The sequence you get is:
> 
>   DATA, true
>   ....
>   DATA, true
>   EMPTY, false
> 
> Because at the time we flush one buffer, we don't know that
> it's the last one, so has_more_events is still true.


Ah, that makes a lot more sense, I can see how that would happen.

Thanks a lot for explaining this to me.

[dsinclair, 2015-06-12 13:48:35]

The patchset sent to the CQ was uploaded after l-g-t-m from kbr@chromium.org
Link to the patchset: https://codereview.chromium.org/1131543003/#ps40001
(title: "test added")

[commit-bot: I haz the power, 2015-06-12 13:49:09]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1131543003/40001

[commit-bot: I haz the power, 2015-06-12 13:53:06]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-06-12 13:53:08]

Try jobs failed on following builders:
  linux_chromium_compile_dbg_32_ng on tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)
  ios_dbg_simulator_ninja on tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/ios_dbg_simulator...)
  mac_chromium_compile_dbg_ng on tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/mac_chromium_comp...)
  mac_chromium_rel_ng on tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/mac_chromium_rel_...)

[hubbe, 2015-06-15 18:10:11]

The CQ bit was checked by hubbe@chromium.org

[hubbe, 2015-06-15 18:10:11]

The patchset sent to the CQ was uploaded after l-g-t-m from
dsinclair@chromium.org, kbr@chromium.org
Link to the patchset: https://codereview.chromium.org/1131543003/#ps80002
(title: "merged & tested")

[commit-bot: I haz the power, 2015-06-15 18:12:45]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1131543003/80002

[commit-bot: I haz the power, 2015-06-15 18:39:27]

Committed patchset #6 (id:80002)

[commit-bot: I haz the power, 2015-06-15 18:40:29]

Patchset 6 (id:??) landed as
https://crrev.com/90388fdeec253d178bb69366f6222c71f9cc38a4
Cr-Commit-Position: refs/heads/master@{#334421}