981851 - Telemetry logging

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Benjamin Smedberg]

I'd like to add a new data type to telemetry: a log of important or unusual events.

It should be possible for both C++ and JS code to write log events. A log event will be described a string key and 0 or more string values. So e.g. "telemetry.experiments.logInstall" ["[e-mail]"]

I expect writing to this log will be fairly uncommon and so I don't want to worry about pre-registering log keys (nothing like histograms.json). Telemetry will record the events in order and also add a firefox-uptime number.

In the telemetry ping this will be recorded as

{
  ...
  log: [
    {key: "telemetry.experiments.logInstall", ts: 600, data: ["[e-mail]"]},
    ...
  ]
}

My intention is to use this in bug 974024 and so get this landed this week for Firefox 30. At this time I don't plan to do any throttling or size-limiting of the log, although that may be important in future revisions.

I'll file dashboarding requests separately.

Comment 1

[Benjamin Smedberg]

Attachment: Telemetry logging, rev. 1

Comment 2

[Bobby Holley (:bholley)]

Comment on attachment 8389338 [details] [diff] [review]
Telemetry logging, rev. 1

Review of attachment 8389338 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/components/telemetry/Telemetry.cpp
@@ +2313,5 @@
> +  entry->data.MoveElementsFrom(aData);
> +}
> +
> +NS_IMETHODIMP
> +TelemetryImpl::LogEvent(const nsACString &aEventID, JS::HandleValue aData,

Hm. Why can't we just use an XPIDL array of strings here?

@@ +2327,5 @@
> +  JS::Rooted<JSString*> str(cx);
> +  JS::Rooted<JSFlatString*> flatstr(cx);
> +  while (true) {
> +    bool done;
> +    if (!iter.next(&item, &done)) {

NS_WARN_IF?

@@ +2334,5 @@
> +    if (done) {
> +      break;
> +    }
> +    str = JS::ToString(cx, item);
> +    flatstr = JS_FlattenString(cx, str);

You need to null-check this. But I think it's probably better to do:

nsDependentJSString depStr;
if (NS_WARN_IF(!depStr.init(cx, str))) {
  return NS_ERROR_OUT_OF_MEMORY;
}

And bypass flatstr;

@@ +2351,5 @@
> +                             s.Length());
> +}
> +
> +NS_IMETHODIMP
> +TelemetryImpl::GetEventLog(JSContext* cx, JS::MutableHandleValue ret)

I'm not really wild about this function. Can't we define an XPIDL interface type for the log entry, and return an array of those? That would let XPConnect do the heavy lifting.

Comment 3

[Benjamin Smedberg]

> > +TelemetryImpl::LogEvent(const nsACString &aEventID, JS::HandleValue aData,
> 
> Hm. Why can't we just use an XPIDL array of strings here?

The XPIDL declaration for an array of strings requires the extra size_is parameter, so:

void logEvent(in AUTF8String id, [array, size_is(dataLength)] in wchar data, in uint32_t dataLength);

And the callers would have to call .logEvent("key", [val1, val2, val3], 3);

And since I want this to be the JS-facing API, that's really not acceptable.

> @@ +2351,5 @@
> > +                             s.Length());
> > +}
> > +
> > +NS_IMETHODIMP
> > +TelemetryImpl::GetEventLog(JSContext* cx, JS::MutableHandleValue ret)
> 
> I'm not really wild about this function. Can't we define an XPIDL interface
> type for the log entry, and return an array of those? That would let
> XPConnect do the heavy lifting.

I can, yes. That doesn't happen to be the way the rest of telemetry works and so it will require a bit of extra JS to convert the list of objects back into normal JS so that they end up in the ping properly. Is that preferable?

Comment 4

[(dormant account)]

Comment on attachment 8389338 [details] [diff] [review]
Telemetry logging, rev. 1

This feels like something that should be done in JS.

Feels like you are going to be recording most data in JS, then serializing it in telemetry. Why do anything in C++?

Comment 5

[(dormant account)]

(In reply to Taras Glek (:taras) from comment #4)
> Feels like you are going to be recording most data in JS, then serializing
> it in telemetry. Why do anything in C++?

in telemetry JS that is

Comment 6

[Bobby Holley (:bholley)]

(In reply to Benjamin Smedberg  [:bsmedberg] from comment #3)
> > > +TelemetryImpl::LogEvent(const nsACString &aEventID, JS::HandleValue aData,
> > 
> > Hm. Why can't we just use an XPIDL array of strings here?
> 
> The XPIDL declaration for an array of strings requires the extra size_is
> parameter, so:
> 
> void logEvent(in AUTF8String id, [array, size_is(dataLength)] in wchar data,
> in uint32_t dataLength);
> 
> And the callers would have to call .logEvent("key", [val1, val2, val3], 3);
> 
> And since I want this to be the JS-facing API, that's really not acceptable.

Oh right, yuck. It'd be nice if XPConnect could somehow auto-fill missing size_is parameters for bonafide arrays, but that's probably more trouble than it's worth.

> > I'm not really wild about this function. Can't we define an XPIDL interface
> > type for the log entry, and return an array of those? That would let
> > XPConnect do the heavy lifting.
> 
> I can, yes. That doesn't happen to be the way the rest of telemetry works
> and so it will require a bit of extra JS to convert the list of objects back
> into normal JS so that they end up in the ping properly. Is that preferable?

I think so, yeah. We really want to minimize the amount of raw JSAPI-munging that happens outside of C++ and binding code.

Comment 7

[(dormant account)]

Comment on attachment 8389338 [details] [diff] [review]
Telemetry logging, rev. 1

Review of attachment 8389338 [details] [diff] [review]:
-----------------------------------------------------------------

forgot to r- due to approach

Comment 8

[Benjamin Smedberg]

I do expect to be using this from C++ from time to time, but not at first. How about a nsITelemetryLog implemented in JS?

Comment 9

[Benjamin Smedberg]

Attachment: Telemetry logging in JS, rev. 2

since C++ isn't required and XPIDL is a PITA, I'm just going with JS for now and I can add C++ later if necessary via webidl bindings or something.

Comment 10

[Benjamin Smedberg]

Attachment: rev 2 tests

Forgot to include the tests from the previous revision.

Comment 11

[(dormant account)]

Comment on attachment 8389499 [details] [diff] [review]
Telemetry logging in JS, rev. 2

This looks much better. 

I've been doing a lot of time series logging with graphite lately. I think the graphite approach nets the same data, but results in a smaller stream to send on the clientside, esp after compression.

Instead of telemetry.log = {{ts:0, data:"foo"},{ts:1,data:"goo"},...}, is it feasible to do

telemetry.log={"foo":{0,....}, "goo":{1,....}). This can be reassembled into the same format as you propose on the serverside but has 2 advantages:
a) much better data/json-schema ratio
b) should result in better compression, leaves room for further optimization such as using more densely packed arrays

This should also be friendlier to import into various timeseries databases for analysis such as graphite or influxdb

Comment 12

[(dormant account)]

Comment on attachment 8389773 [details] [diff] [review]
rev 2 tests

I don't think I'll need to review this again

Comment 13

[Benjamin Smedberg]

Attachment: Telemetry logging in JS, rev. 2.1

Taras and I discussed in IRC. He proposed a schema where multiple events of the same type get aggregated into buckets like so:

log: {
  "key1": [time1, time4, time5],
  "key2": [time2, time3]
};

In this case however we need to be able to store data with the event (not a lot, but an arbitrary string that doesn't fit into a neat key.value.value structure). So I cleaned up the data format a little so that it serializes into just arrays so:

log: [
  ["id", timeinms, "data1"],
  ["id2", timeinms, "data1", "data2"],
];

Please accept this approach for now since we only expect to be logging two events per session for now, and expect that we may add the other time-series approach that we might want for logging memory data will need a more compact representation later that we can import using standard tools.

Comment 14

[(dormant account)]

Comment on attachment 8390705 [details] [diff] [review]
Telemetry logging in JS, rev. 2.1

r+ for most of the patch. Don't use non-int time values in telemetry. Please submit another patch to only expose int ms values (like Date.now())

Comment 15

[Benjamin Smedberg]

https://hg.mozilla.org/integration/mozilla-inbound/rev/cd1bb57c45f9

The Math.floor() keeps the telemetry payload as ints, so I think we're good here.

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/cd1bb57c45f9