Track merged nudge sources

Track merged nudge sources

There's a lot of valuable information in coalesced nudges.  Currently, one
nudge source can overwrite another, which leaves us in the dark as to why the
client behaved a certain way.  In fact, today we can't even determine whether
or not any coalescing was done.  

By logging all the coalesced sources and their payloads, we can learn a lot
more about client behaviour.  I'm hoping to use this to improve our
notification effectiveness metrics.

BUG=138613
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=170549

[rlarocque, 2012-11-21 21:31:50]

Tim: Here's the patch we were just discussing.  I was going to send it out for
review fairly soon anyway, and this could provide more context for our
discussion.

Raz: Would you have any use for notification hints stored in the debug info?  If
not, I can reduce the network traffic cost of the debug info by storing a bool
instead.

https://codereview.chromium.org/11416126/diff/1/sync/internal_api/debug_info_...
File sync/internal_api/debug_info_event_listener.cc (right):

https://codereview.chromium.org/11416126/diff/1/sync/internal_api/debug_info_...
sync/internal_api/debug_info_event_listener.cc:61:
pb_type_hint->set_notification_hint(type_iter->second.payload);
The addition of this field could make DebugInfo much more expensive.  It
effectively doubles the number of times we send up the notification hint.

If that's a concern, I can change this to a bool 'payload_not_empty'.  That
would not affect my research, though others might prefer to have the payloads
available.

https://codereview.chromium.org/11416126/diff/1/sync/internal_api/debug_info_...
sync/internal_api/debug_info_event_listener.cc:147: void
DebugInfoEventListener::OnNudgeFromDatatype(ModelType datatype) {
I think this becomes redundant when the new information is added.  It's a bit
different in that it isn't tied to sync cycles, so it can report different
results if there is a failed + retried sync cycle, or in some rare race
conditions.  I prefer the behaviour of the new info, though.

https://codereview.chromium.org/11416126/diff/1/sync/internal_api/debug_info_...
sync/internal_api/debug_info_event_listener.cc:155: void
DebugInfoEventListener::OnIncomingNotification(
I believe this also becomes redundant.

[Raz Mathias, 2012-11-27 21:52:18]

https://codereview.chromium.org/11416126/diff/3001/sync/protocol/client_debug...
File sync/protocol/client_debug_info.proto (right):

https://codereview.chromium.org/11416126/diff/3001/sync/protocol/client_debug...
sync/protocol/client_debug_info.proto:19: optional string notification_hint = 2;
To your question above, a bool would be better -- I think since the notification
payload is already being sent separately it would be best not to resend it here.

[tim (not reviewing), 2012-11-27 23:48:47]

https://codereview.chromium.org/11416126/diff/3001/sync/sessions/sync_session.cc
File sync/sessions/sync_session.cc (right):

https://codereview.chromium.org/11416126/diff/3001/sync/sessions/sync_session...
sync/sessions/sync_session.cc:94: // When we coalesce sessions, the sync update
source gets overwritten with the
Update comment.   Also, you say "merged" but you're only appending to a vector,
right?  In some instances we'll actually wind up appending a source that is
known to be the same as the one that's already in merged_sources_log_.  Should
we be smart about that, even though I think the only two cases are line 271 and
1023 in sync_scheduler_impl.cc, both of which should be removed?

[rlarocque, 2012-11-28 00:33:58]

https://codereview.chromium.org/11416126/diff/3001/sync/sessions/sync_session.cc
File sync/sessions/sync_session.cc (right):

https://codereview.chromium.org/11416126/diff/3001/sync/sessions/sync_session...
sync/sessions/sync_session.cc:94: // When we coalesce sessions, the sync update
source gets overwritten with the
On 2012/11/27 23:48:47, timsteele wrote:
> Update comment.   Also, you say "merged" but you're only appending to a
vector,
> right?  In some instances we'll actually wind up appending a source that is
> known to be the same as the one that's already in merged_sources_log_.  Should
> we be smart about that, even though I think the only two cases are line 271
and
> 1023 in sync_scheduler_impl.cc, both of which should be removed?

I think the comment should stay the same.  The 'merged_sources_log' is only used
for debugging.  The coalesce logic for the source and payloads we report to the
server remains the same.

When I wrote this, I was thinking of "merged_sources_log" as a log of the
sources that have been merged into the one we finally ended up using.  The log
itself is not merged.  I can see how the name can be misleading, though.  I
should use a different name for this.  How about debug_info_sources_list?

I can't think of a strong reason to be smart about merging common sources. 
AFAIK, the costs of storing and sending multiple copies is not that high.  It
could be useful to see the sequence of events that led to a sync cycle exactly
as the syncer saw them.

Also, I'm not sure I understand your comment about the two cases.  What about
lines 502 and 632?

[rlarocque, 2012-11-29 01:58:00]

I've replaced the notification hint with a bool and renamed some variables. 
PTAL.

[tim (not reviewing), 2012-11-29 19:28:04]

LGTM with nit.

https://codereview.chromium.org/11416126/diff/1009/sync/protocol/client_debug...
File sync/protocol/client_debug_info.proto (right):

https://codereview.chromium.org/11416126/diff/1009/sync/protocol/client_debug...
sync/protocol/client_debug_info.proto:54: repeated SourceInfo source_info = 11;
sources_list may be a better name (to match debug_info_sources_list more
closely).  A comment explaining how this gets populated would be good too.  You
might consider giving a heads up to someone using this to debug that no efforts
are made to avoid spurious / duplicate back-to-back entries in this list,  (as
canary jobs and mode switches (client side) will cause this, for the moment).

[rlarocque, 2012-11-29 23:42:12]

https://codereview.chromium.org/11416126/diff/1009/sync/protocol/client_debug...
File sync/protocol/client_debug_info.proto (right):

https://codereview.chromium.org/11416126/diff/1009/sync/protocol/client_debug...
sync/protocol/client_debug_info.proto:54: repeated SourceInfo source_info = 11;
On 2012/11/29 19:28:05, timsteele wrote:
> sources_list may be a better name (to match debug_info_sources_list more
> closely).  

I thought of that, but then there's the problem that the protobuf generated
function names don't make sense.  I think add_source_info() is a more accurate
function name than add_sources_list(), so that's why I kept the field name
singular.

> A comment explaining how this gets populated would be good too.  You
> might consider giving a heads up to someone using this to debug that no
efforts
> are made to avoid spurious / duplicate back-to-back entries in this list,  (as
> canary jobs and mode switches (client side) will cause this, for the moment). 
 

Good point.  Will fix.

[rlarocque, 2012-11-30 00:45:24]

Comment added.

Tim, would you be OK with leaving the field name the same, for the reasons
listed in the previous comment?

[tim (not reviewing), 2012-11-30 00:47:00]

On 2012/11/30 00:45:24, rlarocque wrote:
> Comment added.
> 
> Tim, would you be OK with leaving the field name the same, for the reasons
> listed in the previous comment?

Yeah, that seems fine.

[commit-bot: I haz the power, 2012-11-30 19:14:04]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/rlarocque@chromium.org/11416126/13001

[commit-bot: I haz the power, 2012-11-30 21:32:25]

Change committed as 170549

[Nicolas Zea, 2012-11-30 21:46:37]

https://chromiumcodereview.appspot.com/11416126/diff/13001/sync/protocol/clie...
File sync/protocol/client_debug_info.proto (right):

https://chromiumcodereview.appspot.com/11416126/diff/13001/sync/protocol/clie...
sync/protocol/client_debug_info.proto:58: optional GetUpdatesCallerInfo
caller_info = 10;
out of curiosity, should this field be deprecated now?

[rlarocque, 2012-11-30 21:53:09]

https://chromiumcodereview.appspot.com/11416126/diff/13001/sync/protocol/clie...
File sync/protocol/client_debug_info.proto (right):

https://chromiumcodereview.appspot.com/11416126/diff/13001/sync/protocol/clie...
sync/protocol/client_debug_info.proto:58: optional GetUpdatesCallerInfo
caller_info = 10;
On 2012/11/30 21:46:37, Nicolas Zea wrote:
> out of curiosity, should this field be deprecated now?

I'll admit it's a bit redundant.  This will tell us what the client actually
sent up in the previously completed sync cycle.  The newly added counters below
will tell us all the sources that were merged together to form the caller_info
that was eventually sent.  

Although it should be possible to derive caller_info from source_info, it's not
trivial.  And I can foresee sawzall queries where we might want one or the
other.  Storing both will make some queries more convenient.

I think we should keep both for now and audit these fields once the scheduler
refactor is complete.