1174612 - Make MEMORY STAT logging less verbose

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Birunthan Mohanathas [:poiru]]

Currently, each test generates 3 or 4 lines of MEMORY STAT messages:

  20:18:05     INFO -  MEMORY STAT vsize after test: 581251072
  20:18:05     INFO -  MEMORY STAT residentFast after test: 146239488
  20:18:05     INFO -  MEMORY STAT heapAllocated after test: 68727408
  20:18:05     INFO -  4 INFO TEST-OK | test.html | took 183ms

We should consolidate all of these into the test end message in a compact format:

  20:18:05     INFO -  4 INFO TEST-OK | test.html | took 183ms | MEMSTAT(vs=581251072 rf=146239488 ha=68727408)

Shu, Ryan, any objections?

Comment 1

[Birunthan Mohanathas [:poiru]]

(In reply to Birunthan Mohanathas [:poiru] from comment #0)
> We should consolidate all of these into the test end message in a compact
> format:
> 
>   20:18:05     INFO -  4 INFO TEST-OK | test.html | took 183ms |
> MEMSTAT(vs=581251072 rf=146239488 ha=68727408)

We could also use megabytes (or at least kilobytes):

  20:18:05     INFO -  4 INFO TEST-OK | test.html | took 183ms | MEMSTAT(vs=581 rf=146 ha=68)

Comment 2

[Ryan VanderMeulen [:RyanVM]]

I think they should be on a separate line from the test result still, but agree that consolidating them down to one line makes a lot of sense.

Comment 3

[Andrew McCreight [:mccr8]]

Having all of the memory stats on a single line and using MB sound fine to me, but please take a few extra characters and make it something comprehensible. Something more like
MEMORY STAT | vsize 581mb | residentFast 146mb | heapAllocated 68mb
This spells out what it actually is, and gives the units. Without that, you might as well just print out the numbers and nothing else, because people are going to have to look up what they mean anyways.

Comment 4

[Birunthan Mohanathas [:poiru]]

Attachment: Consolidate MEMORY STAT messages into a single line

This uses the format from comment 3.

Comment 5

[Chris Manchester (Mostly offline until Aug 26))]

Comment on attachment 8622529 [details] [diff] [review]
Consolidate MEMORY STAT messages into a single line

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

This looks ok, but I think there are out of tree consumers of these logs that would break with this change. Maybe shu can advise.

Comment 6

[Shu-yu Guo [:shu]]

https://github.com/syg/mochimem/tree/master will break, but it will be easy to fix.

I also agree with what mccr8 said in comment 3. Please needinfo me again when this lands and I will update mochimem.

Comment 7

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/4d9c70392f0e

Comment 8

[Ryan VanderMeulen [:RyanVM]]

Backed out for blowing up mochitests across the board.
https://treeherder.mozilla.org/logviewer.html#?job_id=10797902&repo=mozilla-inbound

https://hg.mozilla.org/integration/mozilla-inbound/rev/084681545e43

Comment 9

[Pulsebot]

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

Comment 10

[Birunthan Mohanathas [:poiru]]

Try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=d93d1dddc58e

Comment 11

[Ryan VanderMeulen [:RyanVM]]

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

Comment 12

[Birunthan Mohanathas [:poiru]]

ni? for comment 6.

Comment 13

[Shu-yu Guo [:shu]]

Birunthan, sorry, should've caught this earlier:

Since this data is supposed to be machine-consumed, the "mb" suffix (or other sizes) is not preferred here.

Could you do "MEMORY STAT | vsize 123456 | residentFast 123456 | heapAllocated 123456"?

Comment 14

[Andrew McCreight [:mccr8]]

(In reply to Shu-yu Guo [:shu] from comment #13)
> Since this data is supposed to be machine-consumed, the "mb" suffix (or
> other sizes) is not preferred here.
What do you mean? People read this data manually out of the logs, too.

Comment 15

[Shu-yu Guo [:shu]]

(In reply to Andrew McCreight [:mccr8] from comment #14)
> (In reply to Shu-yu Guo [:shu] from comment #13)
> > Since this data is supposed to be machine-consumed, the "mb" suffix (or
> > other sizes) is not preferred here.
> What do you mean? People read this data manually out of the logs, too.

Oh really? Those are cumulative numbers, without showing a chart like mochimem does, how are they individually consumable?

Comment 16

[Shu-yu Guo [:shu]]

s/consumable/interpreted

Comment 17

[Andrew McCreight [:mccr8]]

I think one of the sheriffs said that if they start seeing weird OOM-y looking behavior they can check out the memory in the logs around the test where bad stuff started happening.

Comment 18

[Shu-yu Guo [:shu]]

(In reply to Andrew McCreight [:mccr8] from comment #17)
> I think one of the sheriffs said that if they start seeing weird OOM-y
> looking behavior they can check out the memory in the logs around the test
> where bad stuff started happening.

Huh, okay. We can leave it as is then I suppose.