1328198 - SyntaxError: JSON.parse: expected double-quoted property name at line 1 column 46 of the JSON data

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P3)

Description

[Guilherme Lima]

On latest Nightly, Browser Console is spammed with a lot of
SyntaxError: JSON.parse: expected double-quoted property name at line 1 column 46 of the JSON data     GCTelemetry.jsm:194:16
which points to 'let data = JSON.parse(arg);' in view-source:resource://gre/modules/GCTelemetry.jsm
Don't know when the problem appeared.

Comment 1

[Georg Fritzsche [:gfritzsche]]

Bill, can you take a look at this?

Comment 2

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Steve, might anything have changed recently that would produce invalid JSON from the GC statistics?

Comment 3

[Steve Fink [:sfink] [:s:]]

(In reply to Bill McCloskey (:billm) from comment #2)
> Steve, might anything have changed recently that would produce invalid JSON
> from the GC statistics?

Yes. I switched the GC stats to mozilla::Time{Stamp,Duration} in bug 1173354, which ended up touching lots of the formatting code. I must have mangled this. I'll take a look.

Comment 4

[Steve Fink [:sfink] [:s:]]

I have not been able to reproduce this. The JSON in my test is ok, and I do not see any of these message on the console.

Going on the theory that the fields are often fixed-width, column 46 looks like the value of total_time, which is total.ToMilliseconds(). I don't know what would be produced on OOM in a non-DEBUG build (see bug 1326343); I should land that, but it seems unlikely to be the culprit.

If I understood how the browser plumbing worked, perhaps I could give you a way to insert your own garbage-collection-statistics observer and dump out the value in this situation. But I don't.

Is this still happening? Do you have the pref javascript.options.mem.notify set?

I tried turning on the pref, then running the following code in Scratchpad, but got no console messages in my Nightly (successful or otherwise):

Components.utils.import('resource://gre/modules/Services.jsm');
function observer(subject, topic, json) {
    var data = JSON.parse(json);
    console.log("Parsed gc stats ok");
}
Services.obs.addObserver(observer, "garbage-collection-statistics", false);

I imagine there's a good reason why that didn't work, but I don't know enough to know what it is.

Comment 5

[Guilherme Lima]

I had 'javascript.options.mem.notify' as false. Changed it to true and ran the code, but all I got was
/*
Exception: TypeError: Components.utils is undefined
@Scratchpad/1:10:1
*/

Maybe I have to change another config beside 'javascript.options.mem.notify' to true to make the code work?

Comment 6

[Steve Fink [:sfink] [:s:]]

No, you're running in content mode (the default). You'd have to change to browser mode in the Environment tab. But it still doesn't work. For me, at least.

Comment 7

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

(In reply to Steve Fink [:sfink] [:s:] from comment #6)
> No, you're running in content mode (the default). You'd have to change to
> browser mode in the Environment tab. But it still doesn't work. For me, at
> least.

And to do that, you need to follow these instructions:
https://developer.mozilla.org/en-US/docs/Tools/Scratchpad#Running_Scratchpad_in_the_browser_context

Strangely, Steve's code works for me. I see "Parsed gc stats ok" in the console.

Comment 8

[Guilherme Lima]

/*
Exception: SyntaxError: missing } after function body
WCA_evalWithDebugger@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webconsole.js:1366:16
WCA_onEvaluateJS@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webconsole.js:898:20
WCA_onEvaluateJSAsync@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webconsole.js:868:20
onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js:1776:15
send/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/transport/transport.js:570:13
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
*/

I hope I got things right!

Comment 9

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

That doesn't look right. I think you might have missed some of the code or something (maybe a '{').

Comment 10

[Guilherme Lima]

With Scratchpad alerting me to "This scratchpad executes in the Browser context." pasting only the code pointed by sfink, and clicking in Display, I get:
/*
undefined
*/

Comment 11

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

That sounds better. Do you see anything in the browser console after that?

Comment 12

[Guilherme Lima]

Just a bunch of
SyntaxError: JSON.parse: expected double-quoted property name at line 1 column 46 of the JSON data[Learn More] Scratchpad/4:12:16
which points to 'console.log("Parsed gc stats ok");'

Comment 13

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

OK, I think it's working! Unfortunately Steve's snippet doesn't give us the data we need. Can you run this in the same way?

Components.utils.import('resource://gre/modules/Services.jsm');
function observer(subject, topic, json) {
    console.log("GC JSON", json);
    var data = JSON.parse(json);
    console.log("Parsed gc stats ok");
}
Services.obs.addObserver(observer, "garbage-collection-statistics", false);

With that, we'll be able to see the JSON that's giving the error. A big string will appear in the console starting with "GC JSON". Please attach the rest to the bug.

Comment 14

[Guilherme Lima]

GC JSON {"timestamp":1483674960219000,"max_pause":33,120,"total_time":146,346,"zones_collected":2,"total_zones":8,"total_compartments":448,"minor_gcs":12,"store_buffer_overflows":0,"mmu_20ms":0,"mmu_50ms":33,"scc_sweep_total":5,246,"scc_sweep_max_pause":5,246,"nonincremental_reason":"None","allocated":36,"added_chunks":0,"removed_chunks":0,"slices":[{"slice":0,"pause":11,026,"when":0,000,"reason":"CC_WAITING","initial_state":"NotActive","final_state":"Mark","budget":"10ms","page_faults":52,"start_timestamp":11598,700,"end_timestamp":11598,711,"times":{"wait_background_thread":0,017,"mark_discard_code":1,037,"purge":0,070,"mark":5,610,"mark_roots":3,758,"buffer_gray_roots":2,011,"mark_cross_compartment_wrappers":0,461,"mark_c_and_js_stacks":0,001,"mark_embedding":0,103,"mark_compartments":0,954,"unmark":0,792,"minor_gcs_to_evict_nursery":2,349,"mark_roots":0,227,"mark_c_and_js_stacks":0,002}},{"slice":1,"pause":10,083,"when":49,295,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":0,"start_timestamp":11598,750,"end_timestamp":11598,760,"times":{"wait_background_thread":0,000,"mark":9,091,"minor_gcs_to_evict_nursery":0,971}},{"slice":2,"pause":10,038,"when":73,961,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":3,"start_timestamp":11598,774,"end_timestamp":11598,784,"times":{"wait_background_thread":0,000,"mark":9,775,"minor_gcs_to_evict_nursery":0,228}},{"slice":3,"pause":10,029,"when":98,869,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":1,"start_timestamp":11598,799,"end_timestamp":11598,809,"times":{"wait_background_thread":0,001,"mark":9,951,"minor_gcs_to_evict_nursery":0,056}},{"slice":4,"pause":10,031,"when":122,848,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":6,"start_timestamp":11598,823,"end_timestamp":11598,833,"times":{"wait_background_thread":0,000,"mark":9,975,"minor_gcs_to_evict_nursery":0,025}},{"slice":5,"pause":10,024,"when":146,961,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":0,"start_timestamp":11598,847,"end_timestamp":11598,857,"times":{"wait_background_thread":0,000,"mark":9,978,"minor_gcs_to_evict_nursery":0,027}},{"slice":6,"pause":10,117,"when":170,167,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":0,"start_timestamp":11598,871,"end_timestamp":11598,881,"times":{"wait_background_thread":0,001,"mark":10,073,"minor_gcs_to_evict_nursery":0,024}},{"slice":7,"pause":10,015,"when":192,776,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":0,"start_timestamp":11598,893,"end_timestamp":11598,903,"times":{"wait_background_thread":0,001,"mark":9,968,"minor_gcs_to_evict_nursery":0,027}},{"slice":8,"pause":33,120,"when":303,537,"reason":"INTER_SLICE_GC","initial_state":"Mark","final_state":"Mark","budget":"40ms","page_faults":0,"start_timestamp":11599,004,"end_timestamp":11599,037,"times":{"wait_background_thread":0,000,"mark":33,078,"minor_gcs_to_evict_nursery":0,024}},{"slice":9,"pause":31,729,"when":436,949,"reason":"INTER_SLICE_GC","initial_state":"Mark","final_state":"Finalize","budget":"40ms","page_faults":696,"start_timestamp":11599,137,"end_timestamp":11599,169,"times":{"wait_background_thread":0,001,"mark":0,050,"mark_delayed":0,007,"sweep":30,220,"mark_during_sweeping":5,186,"mark_incoming_black_pointers":0,011,"mark_weak":0,539,"mark_incoming_gray_pointers":0,005,"mark_gray":4,333,"mark_gray_and_weak":0,293,"finalize_start_callbacks":0,373,"per_slice_weak_callback":0,079,"per_compartment_weak_callback":0,292,"sweep_compartments":18,194,"sweep_discard_code":0,609,"sweep_cross_compartment_wrappers":1,944,"sweep_type_objects":0,145,"sweep_breakpoints":1,063,"sweep_miscellaneous":0,719,"sweep_type_information":13,501,"sweep_type_tables_and_compilations":0,001,"free_type_arena":0,007,"sweep_object":0,545,"sweep_string":0,075,"sweep_script":0,402,"sweep_scope":0,000,"sweep_shape":0,946,"sweep_jit_code":0,057,"finalize_end_callback":0,378,"deallocate":1,191,"minor_gcs_to_evict_nursery":0,524,"mark_roots":0,203,"mark_c_and_js_stacks":0,001}},{"slice":10,"pause":0,076,"when":536,336,"reason":"REFRESH_FRAME","initial_state":"Finalize","final_state":"Decommit","budget":"10ms","page_faults":1,"start_timestamp":11599,237,"end_timestamp":11599,237,"times":{"wait_background_thread":0,001,"sweep":0,017,"deallocate":0,017,"minor_gcs_to_evict_nursery":0,025}},{"slice":11,"pause":0,058,"when":637,091,"reason":"INTER_SLICE_GC","initial_state":"Decommit","final_state":"NotActive","budget":"40ms","page_faults":4,"start_timestamp":11599,338,"end_timestamp":11599,338,"times":{"wait_background_thread":0,001,"minor_gcs_to_evict_nursery":0,022}}],"totals":{"wait_background_thread":0,025,"mark_discard_code":1,037,"purge":0,070,"mark":107,551,"mark_roots":3,758,"buffer_gray_roots":2,011,"mark_cross_compartment_wrappers":0,461,"mark_c_and_js_stacks":0,001,"mark_embedding":0,103,"mark_compartments":0,954,"unmark":0,792,"mark_delayed":0,007,"sweep":30,236,"mark_during_sweeping":5,186,"mark_incoming_black_pointers":0,011,"mark_weak":0,539,"mark_incoming_gray_pointers":0,005,"mark_gray":4,333,"mark_gray_and_weak":0,293,"finalize_start_callbacks":0,373,"per_slice_weak_callback":0,079,"per_compartment_weak_callback":0,292,"sweep_compartments":18,194,"sweep_discard_code":0,609,"sweep_cross_compartment_wrappers":1,944,"sweep_type_objects":0,145,"sweep_breakpoints":1,063,"sweep_miscellaneous":0,719,"sweep_type_information":13,501,"sweep_type_tables_and_compilations":0,001,"free_type_arena":0,007,"sweep_object":0,545,"sweep_string":0,075,"sweep_script":0,402,"sweep_scope":0,000,"sweep_shape":0,946,"sweep_jit_code":0,057,"finalize_end_callback":0,378,"deallocate":1,207,"minor_gcs_to_evict_nursery":4,302,"mark_roots":0,430,"mark_c_and_js_stacks":0,004,"barriers":4,904,"unmark_gray":4,584}} Scratchpad/6:13:5

Comment 15

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Ah. It's the ,/. internationalization thing. So this did regress with bug 1173354. Previously we printed the decimal point ourselves.

Comment 16

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Also, thanks Guilherme! We have everything we need now.

Comment 18

[Steve Fink [:sfink] [:s:]]

Attachment: Fix locale-dependence in GC statistics JSON output

Revert back to using %llu.%03llu instead of %.3f. I totally forgot that that's why it was written that way. Ugh.

Comment 19

[Steve Fink [:sfink] [:s:]]

Attachment: Fix locale-dependence in GC statistics JSON output

Ok, this time reporting milliseconds.

Comment 20

[Jon Coppeard (:jonco)]

Comment on attachment 8828932 [details] [diff] [review]
Fix locale-dependence in GC statistics JSON output

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

Kinda gross but necessary.

Thanks for adding the comments.

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/43346af8aae0
Fix locale-dependence in GC statistics JSON output, r=jonco

Comment 22

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/43346af8aae0