Closed Bug 981851 Opened 6 years ago Closed 6 years ago

Telemetry logging

Categories

(Toolkit :: Telemetry, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla30

People

(Reporter: benjamin, Assigned: benjamin)

References

Details

Attachments

(3 files, 1 obsolete file)

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" ["firefox-translation-experiment-v1@mozilla.org"]

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: ["firefox-translation-experiment-v1@mozilla.org"]},
    ...
  ]
}

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.
Assignee: nobody → benjamin
Status: NEW → ASSIGNED
OS: Mac OS X → All
Hardware: x86 → All
Attached patch Telemetry logging, rev. 1 (obsolete) — Splinter Review
Attachment #8389338 - Flags: review?(taras.mozilla)
Attachment #8389338 - Flags: review?(bobbyholley)
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.
Attachment #8389338 - Flags: review?(bobbyholley)
> > +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?
Flags: needinfo?(bobbyholley)
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++?
(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
(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.
Flags: needinfo?(bobbyholley)
Comment on attachment 8389338 [details] [diff] [review]
Telemetry logging, rev. 1

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

forgot to r- due to approach
Attachment #8389338 - Flags: review?(taras.mozilla) → review-
I do expect to be using this from C++ from time to time, but not at first. How about a nsITelemetryLog implemented in JS?
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.
Attachment #8389338 - Attachment is obsolete: true
Attachment #8389499 - Flags: review?(taras.mozilla)
Attached patch rev 2 testsSplinter Review
Forgot to include the tests from the previous revision.
Attachment #8389773 - Flags: review?(taras.mozilla)
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
Attachment #8389499 - Flags: review?(taras.mozilla)
Comment on attachment 8389773 [details] [diff] [review]
rev 2 tests

I don't think I'll need to review this again
Attachment #8389773 - Flags: review?(taras.mozilla) → review+
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.
Attachment #8390705 - Flags: review?(taras.mozilla)
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())
Attachment #8390705 - Flags: review?(taras.mozilla) → review+
No longer blocks: 974024
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.
https://hg.mozilla.org/mozilla-central/rev/cd1bb57c45f9
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla30
You need to log in before you can comment on or make changes to this bug.