753461 - Write shutdown time to disk

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[(dormant account)]

We should record a timestamp when shutdown is initiated and then use a static destructor to measure approximate time to shutdown. This should then be written out to persistent storage and read back in on the next telemetry ping.

We need this to track improvements in shutdown speed usefully.

Comment 1

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Can you expand a bit on how you want this to be done? I assume it has to be really fast since we don't want to slowdown shutdown too much just to measure it :-)

I guess we can create a file with a fixed name in the profile directory with just a 32 bit integer in it with the number of microseconds it took us to shutdown. Do you think we need anything more?

Comment 2

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Another thing, when should we start the timer?

Comment 3

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

(In reply to Rafael Ávila de Espíndola (:espindola) from comment #2)
> Another thing, when should we start the timer?

from bug 722243, just before sending quit-application-granted I guess.

Comment 4

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: wip patch

Missing proper error checking and actual telemetry reporting.

Comment 5

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: record and report shutdown times

https://tbpl.mozilla.org/?tree=Try&rev=e0aff6fc7e37

Comment 6

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

A version with the missing #include is at
https://tbpl.mozilla.org/?tree=Try&rev=1252237fda09

Comment 7

[(dormant account)]

Comment on attachment 623828 [details] [diff] [review]
record and report shutdown times

+TimeStamp RecordedShutdownStartTime;

s/RecordedShutdownStartTime/gRecordedShutdownStartTime/
why is this not static?

+  RecordedShutdownTimeStampFileName = strdup(aNativePath.get());
I'm not sure how this compiled, windows isn't support to have strdup. use PL_Strdup

+  std::string tmpName = name + ".tmp"; 
use Mozilla strings

+  MOZ_ASSERT(now > RecordedShutdownStartTime);
This could in theory become a random orange. >= seems safer

+  uint32_t diff2 = diff.ToMilliseconds();
use PRUint32 

Should use nspr file io in RecordShutdownEndTimeStamp. I'm confused how this compiles, rename() is a posix functions, where is it coming from on windows?

+  uint32_t diff2 = diff.ToMilliseconds();
+  size_t r = fwrite(&diff2, 4, 1, f);
please write this out as ascii so it can be read back in JS and we don't have to deal with endianness.

+class RecordShutdownEndTimeStampHelper {
+public:
+  ~RecordShutdownEndTimeStampHelper() {
+    RecordShutdownEndTimeStamp();

Why can't you just put the shutdown code in here?
+  }
+};

s/Helper;/gHelper/

Code that you wrote in Telemetry.cpp should be in TelemetryPing.js.

+  // FIXME: Should we differentiate normal cases like the first startup and
+  // 'real' failures?
No.

+      payloadObj.timeToShutdownInMS = Telemetry.timeToShutdownInMS;
This actually belongs in getSimpleMeasurements()

I think no test is better than a useless test in this case.

Comment 8

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: New version

https://tbpl.mozilla.org/?tree=Try&rev=3ff0ea14a977

The main changes are
* Rename the file to ShutdownTime, since we don't actually write a timestamp to it.
* Factor the logic to find the file to a helper function. Avoid having the file name in two places in the code.
* Use the PR_* IO functions and memory management.

The code still has std::strings since it is not clear to me which of the mozilla string functions we should use (or what the problem with std::string is).

I have also kept the implementation in c++ as this is the smallest interface we can have to JS. Reading the file from JS would require at least exposing the filename.

Comment 9

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: new new version

https://tbpl.mozilla.org/?tree=Try&rev=475d733924ad

In addition to previous changes, this one

* Uses only standard integer types
* Uses nsCString

I will add independent patches changing the existing types in Telemetry.cpp and nsAppStartup.cpp.

Comment 10

[(dormant account)]

Comment on attachment 624071 [details] [diff] [review]
new new version

This doesn't address my earlier review comments(writing out the timestamp as text and reading it back via js)

Comment 11

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

> This doesn't address my earlier review comments(writing out the timestamp as
> text and reading it back via js)

Can you expand a bit on why you want that? I commented that changing the code to read from JS would increase the size and complexity of the interface. JS would now need to know what filename is.

I don't see any advantage to doing this (or anything really) from JS and I assumed that you wanted a text format just to read it from JS. Note for example that the slow sql stuff is all in c++.

Comment 12

[(dormant account)]

From our conversation it looks like we have to report shutdown time with saved-data telemetry stuff. Nathan will implement that part.

Comment 13

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: just the write

https://tbpl.mozilla.org/?tree=Try&rev=3cee82157e53

Comment 14

[(dormant account)]

Comment on attachment 624521 [details] [diff] [review]
just the write

Minor nits. Sorry for not spotting these sooner.

stuff like

+static void RecordShutdownStartTimeStamp() {

should be

static void
RecordShutdownStartTimeStamp()
{

+  mozFile->AppendNative(NS_LITERAL_CSTRING("ShutdownTime"));
add a .txt extension and call it Telemetry.ShutdownTime.txt

Also, I just realized that this code should be conditional on Telemetry::CanRecord()

+  if (written == static_cast<uint32_t>(-1) || rv != PR_SUCCESS)
+    return;

should remove the tmp file in case of failure

Comment 15

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: new patch

Comment 16

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: Only check Telemetry::CanRecord once

Comment 17

[(dormant account)]

Comment on attachment 624858 [details] [diff] [review]
Only check Telemetry::CanRecord once

thanks

Comment 18

[Matt Brubeck (:mbrubeck)]

http://hg.mozilla.org/integration/mozilla-inbound/rev/c2e8a029913d

Note: This patch added a static constructor.  :)

Comment 19

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

(In reply to Matt Brubeck (:mbrubeck) from comment #18)
> http://hg.mozilla.org/integration/mozilla-inbound/rev/c2e8a029913d
> 
> Note: This patch added a static constructor.  :)

For this?
 +static TimeStamp gRecordedShutdownStartTime;

I was assuming it would get optimized out, let me check.

Comment 20

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

The only startup code I see is the registration of call to RecordShutdownEndTimeStampHelper::~RecordShutdownEndTimeStampHelper, which we need for now but will go away once we move it when adding a call to _exit(0).

Comment 21

[Justin Lebar (not reading bugmail)]

The timestamp constructor just initializes itself to zero, so since this lives in the .data section, I presume it can be optimized out.

Comment 22

[Matt Brubeck (:mbrubeck)]

"Number of Constructors" increased from 367 to 368 on Linux when this patch landed.  I don't know how that number is measured:
http://graphs.mozilla.org/graph.html#tests=[[81,63,6]]&sel=1337258243000,1337431043000

Comment 23

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

OK, looks like a limitation in gcc.

Right now both clang and gcc produce a function so that they can register the destructor call. That is OK so far as we will be removing that as part of the _exit(0) work.

With

static RecordShutdownEndTimeStampHelper gHelper;

removed, gcc still produces

        .section        .text.startup._GLOBAL__sub_I_nsAppStartup.cpp,"ax",@progbits
        .type   _GLOBAL__sub_I_nsAppStartup.cpp, @function
_GLOBAL__sub_I_nsAppStartup.cpp:
.LFB5453:
        .cfi_startproc
        movq    $0, _ZL26gRecordedShutdownStartTime(%rip)
        ret
        .cfi_endproc

but clang removes it completely.

Taras, do you want me to try to replace gRecordedShutdownStartTime with a POD type?

Comment 24

[Ryan VanderMeulen [:RyanVM]]

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

Comment 25

[(dormant account)]

(In reply to Rafael Ávila de Espíndola (:espindola) from comment #23)

> Taras, do you want me to try to replace gRecordedShutdownStartTime with a
> POD type?

We should do that when we revise the code to cope with exit(0)

Comment 26

[:Irving Reid (No longer working on Firefox)]

The static destructor is causing warnings from XPCOM memory management, at least on Thunderbird:

WARNING: XPCOM objects created/destroyed from static ctor/dtor: file .../comm-central/mozilla/xpcom/base/nsTraceRefcntImpl.cpp, line 140


The warning gets printed five or six times, it looks to me like it is once for each nsCString operation.

Here's an example backtrace:

#0	0x00000001039591b5 in AssertActivityIsLegal() at /Users/ireid/tbird/comm-central/mozilla/xpcom/base/nsTraceRefcntImpl.cpp:140
#1	0x0000000103958ebb in NS_LogAddRef_P at /Users/ireid/tbird/comm-central/mozilla/xpcom/base/nsTraceRefcntImpl.cpp:958
#2	0x000000010397cf75 in nsStringBuffer::Alloc(unsigned long) ()
#3	0x000000010397fc17 in nsACString_internal::MutatePrep(unsigned int, char**, unsigned int*) ()
#4	0x000000010397fdda in nsACString_internal::ReplacePrepInternal(unsigned int, unsigned int, unsigned int, unsigned int) ()
#5	0x000000010398256b in nsACString_internal::ReplacePrep(unsigned int, unsigned int, unsigned int) ()
#6	0x00000001039809b3 in nsACString_internal::Replace(unsigned int, unsigned int, char const*, unsigned int) ()
#7	0x0000000101250013 in nsACString_internal::Append(char const*, unsigned int) ()
#8	0x0000000101293b64 in nsACString_internal::operator+=(char const*) ()
#9	0x0000000102b69dba in RecordShutdownEndTimeStamp() at /Users/ireid/tbird/comm-central/mozilla/toolkit/components/startup/nsAppStartup.cpp:298
#10	0x0000000102b6a831 in RecordShutdownEndTimeStampHelper::~RecordShutdownEndTimeStampHelper() at /Users/ireid/tbird/comm-central/mozilla/toolkit/components/startup/nsAppStartup.cpp:323
#11	0x0000000102b6a055 in RecordShutdownEndTimeStampHelper::~RecordShutdownEndTimeStampHelper() at /Users/ireid/tbird/comm-central/mozilla/toolkit/components/startup/nsAppStartup.cpp:322

Comment 27

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

(In reply to Irving Reid (:irving) from comment #26)
> The static destructor is causing warnings from XPCOM memory management, at
> least on Thunderbird:
> 
> WARNING: XPCOM objects created/destroyed from static ctor/dtor: file
> .../comm-central/mozilla/xpcom/base/nsTraceRefcntImpl.cpp, line 140
> 
> 
> The warning gets printed five or six times, it looks to me like it is once
> for each nsCString operation.

Interesting. I had seen those before while working on other patches, but didn't noticed it in here, but it is possible that I forgot to check again when switching from std::string to nsCString.

What is the best way to solve this, go back to std::string?

Comment 28

[:Irving Reid (No longer working on Firefox)]

> What is the best way to solve this, go back to std::string?

Or use a fixed size char[] to avoid dynamic memory allocation during shutdown. I don't think that's a really big concern, but I'm not familiar enough with how the platform shuts down to know for sure.

Comment 29

[Lukas Blakk [:lsblakk] use ?needinfo]

Tracking this for 15 and asking for a nomination of a mozilla-beta backout of this bug's patch as per bug 763361 comment 26

Comment 30

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: Revert from beta

Sorry, I had no idea this was on my plate. I pushed to try in:

https://tbpl.mozilla.org/?tree=Try&pusher=[e-mail]

Comment 31

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Comment on attachment 649736 [details] [diff] [review]
Revert from beta

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
User impact if declined: 
Testing completed (on m-c, etc.): 
Risk to taking this patch (and alternatives if risky): 
String or UUID changes made by this patch:

Comment 32

[Lukas Blakk [:lsblakk] use ?needinfo]

Comment on attachment 649736 [details] [diff] [review]
Revert from beta

Try is ridiculously backed up and probably won't give us results in time so I'll approve this for Beta and we can watch the results roll in there.

Comment 33

[Lukas Blakk [:lsblakk] use ?needinfo]

http://hg.mozilla.org/releases/mozilla-beta/rev/611896e7d593