Write shutdown time to disk

RESOLVED FIXED in Firefox 15

Status

()

Toolkit
Telemetry
RESOLVED FIXED
5 years ago
3 years ago

People

(Reporter: (dormant account), Assigned: espindola)

Tracking

(Blocks: 1 bug)

unspecified
mozilla15
x86_64
Windows 7
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite -

Firefox Tracking Flags

(firefox15+ fixed)

Details

Attachments

(2 attachments, 6 obsolete attachments)

(Reporter)

Description

5 years ago
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.
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?
Another thing, when should we start the timer?
(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.
Assignee: nobody → respindola
Created attachment 623266 [details] [diff] [review]
wip patch

Missing proper error checking and actual telemetry reporting.
Created attachment 623828 [details] [diff] [review]
record and report shutdown times

https://tbpl.mozilla.org/?tree=Try&rev=e0aff6fc7e37
Attachment #623266 - Attachment is obsolete: true
Attachment #623828 - Flags: review?(taras.mozilla)
A version with the missing #include is at
https://tbpl.mozilla.org/?tree=Try&rev=1252237fda09
(Reporter)

Comment 7

5 years ago
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.
Attachment #623828 - Flags: review?(taras.mozilla) → review-
Created attachment 624043 [details] [diff] [review]
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.
Attachment #623828 - Attachment is obsolete: true
Attachment #624043 - Flags: review?(taras.mozilla)
Created attachment 624071 [details] [diff] [review]
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.
Attachment #624043 - Attachment is obsolete: true
Attachment #624043 - Flags: review?(taras.mozilla)
Attachment #624071 - Flags: review?(taras.mozilla)
(Reporter)

Comment 10

5 years ago
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)
Attachment #624071 - Flags: review?(taras.mozilla) → review-
> 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++.
(Reporter)

Comment 12

5 years ago
From our conversation it looks like we have to report shutdown time with saved-data telemetry stuff. Nathan will implement that part.
Summary: Report shutdown times via telemetry → Write shutdown time to disk
Created attachment 624521 [details] [diff] [review]
just the write

https://tbpl.mozilla.org/?tree=Try&rev=3cee82157e53
Attachment #624071 - Attachment is obsolete: true
Attachment #624521 - Flags: review?(taras.mozilla)
Blocks: 756142
(Reporter)

Comment 14

5 years ago
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
Attachment #624521 - Flags: review?(taras.mozilla) → review-
Created attachment 624796 [details] [diff] [review]
new patch
Attachment #624521 - Attachment is obsolete: true
Attachment #624796 - Flags: review?(taras.mozilla)
Created attachment 624858 [details] [diff] [review]
Only check Telemetry::CanRecord once
Attachment #624796 - Attachment is obsolete: true
Attachment #624796 - Flags: review?(taras.mozilla)
Attachment #624858 - Flags: review?(taras.mozilla)
(Reporter)

Comment 17

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

thanks
Attachment #624858 - Flags: review?(taras.mozilla) → review+
http://hg.mozilla.org/integration/mozilla-inbound/rev/c2e8a029913d

Note: This patch added a static constructor.  :)
Target Milestone: --- → mozilla15
(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.
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).
The timestamp constructor just initializes itself to zero, so since this lives in the .data section, I presume it can be optimized out.
"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
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?
https://hg.mozilla.org/mozilla-central/rev/c2e8a029913d
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Flags: in-testsuite-
Resolution: --- → FIXED
(Reporter)

Comment 25

5 years ago
(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)
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
(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?
> 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.
Blocks: 765306
Depends on: 763361

Updated

5 years ago
Depends on: 771083
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
tracking-firefox15: --- → +
Created attachment 649736 [details] [diff] [review]
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=respindola@mozilla.com
Attachment #649736 - Flags: review?(lsblakk)
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:
Attachment #649736 - Flags: review?(lsblakk) → approval-mozilla-beta?
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.
Attachment #649736 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
http://hg.mozilla.org/releases/mozilla-beta/rev/611896e7d593
status-firefox15: --- → fixed
You need to log in before you can comment on or make changes to this bug.