Create a field trial to test if we can detect good QPC implementations.

Create a field trial to test if we can detect good QPC implementations.

We'd like to use QPC (TimeTicks::HighResNow) for all uses of TimeTicks. It's
likely this will only work on some subset of Windows systems. This field trial
is meant to determine if an implementation is good and if our heuristics are
able to detect a good implementation.

This particular CL checks for an Intel CPU parameter that indicates rdtsc is
consistently incremented. Firefox uses the same check. I hope to determine that
this is in fact correct and on which versions of Windows QPC calls rdtsc
directly.

We can add more heuristics later.

BUG=158234
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=197431

[Ilya Sherman, 2013-04-03 22:57:33]

FYI: You can also include the necessary changes to histograms.xml as part of
this CL:
https://code.google.com/p/chromium/codesearch#chromium/src/tools/metrics/hist...

[jar (doing other things), 2013-04-04 00:26:12]

Please consider two comments below (the nit should probably be changed).

With that... base LGTM.

https://codereview.chromium.org/13583007/diff/1/base/cpu.cc
File base/cpu.cc (right):

https://codereview.chromium.org/13583007/diff/1/base/cpu.cc#newcode144
base/cpu.cc:144: has_nonstoptsc_ = (cpu_info[3] & (1 << 8)) != 0;
nit: unless there is a great reason to write this so compactly, I'd greatly
prefer something like:

has_non_stop_tsc

Even "tsc" bugs me a bit, but I'm not sure about "time_stamp_counter"

hence:
has_non_stop_time_stamp_counter

I don't mind using a special name when there is some crazy intel defined name to
match (example: sse41), but for places where we're not forced to use a name,
perchance we can push toward our style.

https://codereview.chromium.org/13583007/diff/1/chrome/browser/metrics/time_t...
File chrome/browser/metrics/time_ticks_field_trial_win.cc (right):

https://codereview.chromium.org/13583007/diff/1/chrome/browser/metrics/time_t...
chrome/browser/metrics/time_ticks_field_trial_win.cc:57: return;
I'm surprised you don't want a histogram of how often we failed by version,
similar to line 67.

[James Simonsen, 2013-04-04 02:26:51]

On 2013/04/03 22:57:33, Ilya Sherman wrote:
> FYI: You can also include the necessary changes to histograms.xml as part of
> this CL:
>
https://code.google.com/p/chromium/codesearch#chromium/src/tools/metrics/hist...

Done. Didn't know they were in the main tree.

https://codereview.chromium.org/13583007/diff/1/base/cpu.cc
File base/cpu.cc (right):

https://codereview.chromium.org/13583007/diff/1/base/cpu.cc#newcode144
base/cpu.cc:144: has_nonstoptsc_ = (cpu_info[3] & (1 << 8)) != 0;
On 2013/04/04 00:26:13, jar wrote:
> nit: unless there is a great reason to write this so compactly, I'd greatly
> prefer something like:
> 
> has_non_stop_tsc
> 
> Even "tsc" bugs me a bit, but I'm not sure about "time_stamp_counter"
> 
> hence:
> has_non_stop_time_stamp_counter
> 
> I don't mind using a special name when there is some crazy intel defined name
to
> match (example: sse41), but for places where we're not forced to use a name,
> perchance we can push toward our style.

Done.

https://codereview.chromium.org/13583007/diff/1/chrome/browser/metrics/time_t...
File chrome/browser/metrics/time_ticks_field_trial_win.cc (right):

https://codereview.chromium.org/13583007/diff/1/chrome/browser/metrics/time_t...
chrome/browser/metrics/time_ticks_field_trial_win.cc:57: return;
On 2013/04/04 00:26:13, jar wrote:
> I'm surprised you don't want a histogram of how often we failed by version,
> similar to line 67.

Good point. Done.

[darin (slow to review), 2013-04-04 06:15:11]

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
File chrome/browser/metrics/time_ticks_field_trial_win.cc (right):

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
chrome/browser/metrics/time_ticks_field_trial_win.cc:48:
QueryPerformanceCounter(&qpc_now);
Perhaps it would make sense to insert some calls to Sleep(0) to provoke a
context switch?  that might help exacerbate any issues with QPC being out of
sync across CPU cores.

[Sigurður Ásgeirsson, 2013-04-04 12:35:14]

Drive-by, did not review in detail.

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
File chrome/browser/metrics/time_ticks_field_trial_win.cc (right):

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
chrome/browser/metrics/time_ticks_field_trial_win.cc:27: // TODO(simonjam): We
should look for other signals that QPC might be safe and
On Windows XP, QPC is going to be a system call even when the cycle counter
(rdtsc) is used for timing, so QPC will perform poorly compared to a raw rdtsc
instruction.
You could measure this by bracketing your QPC calls by rtdsc calls, and grabbing
the min value of the invocation cost as a metric.
I predict you'll see tens of cycles for QPC on Vista and up, versus a couple of
thousand cycles on XP.

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
chrome/browser/metrics/time_ticks_field_trial_win.cc:38:
base::win::VERSION_WIN_LAST);
nit: wonky indent.

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
chrome/browser/metrics/time_ticks_field_trial_win.cc:48:
QueryPerformanceCounter(&qpc_now);
On 2013/04/04 06:15:11, darin wrote:
> Perhaps it would make sense to insert some calls to Sleep(0) to provoke a
> context switch?  that might help exacerbate any issues with QPC being out of
> sync across CPU cores.

You can also deliberately cycle the thread across cores by playing with
SetThreadAffinityMask. AFAIK, on a successful return from SetThreadAffinityMask,
you'll be running under the new mask, e.g. on a new core if you roll a single
bit around in the mask.

[jar (doing other things), 2013-04-04 16:58:48]

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
File chrome/browser/metrics/time_ticks_field_trial_win.cc (right):

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
chrome/browser/metrics/time_ticks_field_trial_win.cc:48:
QueryPerformanceCounter(&qpc_now);
I was thinking about suggesting a sleep...

but decided it was counter productive.  Sleeps will probably take some
significant time (>1ms) and would probably miss the bug, where the clock moves
backwards (and I'd assume backwards only slightly, like less than 1ms).

Is my analysis incorrect, and does bug surrounding the "clock going backwards as
you change cores" create large (>1ms) deltas that could be detected after a
sleep?

In the end, I conjectured that we'll hopefully detect problems (if any) by
running on sooooo many machines, that a suspend and core switch would hit us in
the middle of the loop.

Maybe it would be nice to ask what core we were on at the start of the loop, and
what core we were on at the end of the loop, and see if things changed?  That
might give us a measure of how often we had a *chance* to identify the bug. I'm
not real sure what the function might be, but perhaps something like
GetLogicalProcessorInformationEx() would give us such info.

On 2013/04/04 06:15:11, darin wrote:
> Perhaps it would make sense to insert some calls to Sleep(0) to provoke a
> context switch?  that might help exacerbate any issues with QPC being out of
> sync across CPU cores.

[Sigurður Ásgeirsson, 2013-04-04 17:17:18]

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
File chrome/browser/metrics/time_ticks_field_trial_win.cc (right):

https://codereview.chromium.org/13583007/diff/7001/chrome/browser/metrics/tim...
chrome/browser/metrics/time_ticks_field_trial_win.cc:49: int delta =
static_cast<int>(qpc_now.QuadPart - qpc_last.QuadPart);
If the whole point of this is to identify when different cores are out of sync
with respect to QPC or rdtsc, then here's perhaps a better way to do it: probe
each core in turn, and to correlate the QPC/rdtsc clock back to the system
clock, or some other known-good time reference.
The resolution of the system clock is a hindrance to this (down to 15ms) but
perhaps this can be done by cycling over cores, busy waiting for a clock tick
and using the edge of the tick as a reference (assuming it's regular and
accurate).

Another sneaky way to do this would be to spawn as many threads as there are
cores, assign each to a different core, hike them all in priority and let them
all block on an event but one.
When the event is signalled, all the threads should unblock more-or-less
simultaneously. By signalling back to the unblocking thread you can bound the
time span this takes across all the threads. If any of the captured clocks is
outside the time span from start to end, then you've caught messed-up clocks.

[James Simonsen, 2013-04-12 01:47:02]

Sorry for the delay... PTAL.

I've added the SetThreadAffinityMask call and a histogram to show if we managed
to change cores.

I believe the MinResolution histogram will show us how expensive QPC is to call.
I expect we'll see clear bimodal behavior in the histogram based on whether it's
a system call or just rdtsc.

I expect changing cores a few times per run will be enough to reveal any skew,
especially when run on lots of machines. So I punted on the more extreme ways of
teasing out skew for now.

[jar (doing other things), 2013-04-12 02:14:54]

Just a question and a nit, but it seems to LG from what I saw (and I'm curious
to see the histograms!).

https://codereview.chromium.org/13583007/diff/16001/chrome/browser/metrics/ti...
File chrome/browser/metrics/time_ticks_field_trial_win.cc (right):

https://codereview.chromium.org/13583007/diff/16001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_field_trial_win.cc:10: #include
"base/metrics/field_trial.h"
Is this actually a field trial?  I don't think you do this probabilistically. I
don't see references to the class etc.

...which then also makes me wonder if you should rename the file to something
like:

time_ticks_experiment_win

or

time_ticks_win_probe

or other??

https://codereview.chromium.org/13583007/diff/16001/tools/metrics/histograms/...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/13583007/diff/16001/tools/metrics/histograms/...
tools/metrics/histograms/histograms.xml:416: <histogram
name="WinTimeTicks.MinResolutionNanoseconds" units="microseconds">
nit: units should be nanoseconds

https://codereview.chromium.org/13583007/diff/16001/tools/metrics/histograms/...
tools/metrics/histograms/histograms.xml:1407: <int value="4" label="7"/>
nit: probably "Windows 7" would be better (so it doesn't look like you didn't
put in a label... and it is displaying a number).

Same thing for "8"

[James Simonsen, 2013-04-12 02:29:46]

https://codereview.chromium.org/13583007/diff/16001/chrome/browser/metrics/ti...
File chrome/browser/metrics/time_ticks_field_trial_win.cc (right):

https://codereview.chromium.org/13583007/diff/16001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_field_trial_win.cc:10: #include
"base/metrics/field_trial.h"
On 2013/04/12 02:14:54, jar wrote:
> Is this actually a field trial?  I don't think you do this probabilistically.
I
> don't see references to the class etc.
> 
> ...which then also makes me wonder if you should rename the file to something
> like:
> 
> time_ticks_experiment_win
> 
> or
> 
> time_ticks_win_probe
> 
> or other??
> 

Good point. No it's not a field trial in the sense of that class.

I went with the first name you suggested.

https://codereview.chromium.org/13583007/diff/16001/tools/metrics/histograms/...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/13583007/diff/16001/tools/metrics/histograms/...
tools/metrics/histograms/histograms.xml:416: <histogram
name="WinTimeTicks.MinResolutionNanoseconds" units="microseconds">
On 2013/04/12 02:14:54, jar wrote:
> nit: units should be nanoseconds

Doh. Fixed.

https://codereview.chromium.org/13583007/diff/16001/tools/metrics/histograms/...
tools/metrics/histograms/histograms.xml:1407: <int value="4" label="7"/>
On 2013/04/12 02:14:54, jar wrote:
> nit: probably "Windows 7" would be better (so it doesn't look like you didn't
> put in a label... and it is displaying a number).
> 
> Same thing for "8"

Done.

[Sigurður Ásgeirsson, 2013-04-12 13:34:02]

looks good, except I think you'll break Chrome on XP if you check this in as-is
:)

https://codereview.chromium.org/13583007/diff/27001/chrome/browser/metrics/ti...
File chrome/browser/metrics/time_ticks_experiment_win.cc (right):

https://codereview.chromium.org/13583007/diff/27001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_experiment_win.cc:69:
GetCurrentProcessorNumber() != starting_core) {
This function is only documented available as of Windows Vista, have you tested
your change on XP test bots?

[James Simonsen, 2013-04-13 02:17:57]

https://codereview.chromium.org/13583007/diff/27001/chrome/browser/metrics/ti...
File chrome/browser/metrics/time_ticks_experiment_win.cc (right):

https://codereview.chromium.org/13583007/diff/27001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_experiment_win.cc:69:
GetCurrentProcessorNumber() != starting_core) {
On 2013/04/12 13:34:02, Sigurður Ásgeirsson wrote:
> This function is only documented available as of Windows Vista, have you
tested
> your change on XP test bots?

We don't have any XP try bots it seems. :(

I added a unit test and made sure the function isn't called on XP. Does that
work? Or will it complain when the DLL is loaded?

[Sigurður Ásgeirsson, 2013-04-14 02:02:27]

If you bind to a function that's not available, your DLL or executable will
fail to load, irrespective of whether you call it or not. I believe we
still have XP test bots on the continuous waterfall, so you'll turn the
waterfall red if you check this in. NB: that's what the waterfall is for,
so don't be shy to check in experimental changes on off-peak hours,
weekends, etc, or by agreement with sheriffs :).

I'd suggest using the Vista only function as a sanity check only (use
GetModule and GetProcAddress to retrieve them, once, not in a loop), and
then test that your assumptions hold. If you successfully set the thread
affinity mask to a single core, you'll be running on that particular core
on return, or else the world will have come to an end IMHO.


On Fri, Apr 12, 2013 at 10:17 PM, <simonjam@chromium.org> wrote:

>
> https://codereview.chromium.**org/13583007/diff/27001/**
>
chrome/browser/metrics/time_**ticks_experiment_win.cc<https://codereview.chromium.org/13583007/diff/27001/chrome/browser/metrics/time_ticks_experiment_win.cc>
> File chrome/browser/metrics/time_**ticks_experiment_win.cc (right):
>
> https://codereview.chromium.**org/13583007/diff/27001/**
>
chrome/browser/metrics/time_**ticks_experiment_win.cc#**newcode69<https://codereview.chromium.org/13583007/diff/27001/chrome/browser/metrics/time_ticks_experiment_win.cc#newcode69>
> chrome/browser/metrics/time_**ticks_experiment_win.cc:69:
> GetCurrentProcessorNumber() != starting_core) {
> On 2013/04/12 13:34:02, Sigurður Ásgeirsson wrote:
>
>> This function is only documented available as of Windows Vista, have
>>
> you tested
>
>> your change on XP test bots?
>>
>
> We don't have any XP try bots it seems. :(
>
> I added a unit test and made sure the function isn't called on XP. Does
> that work? Or will it complain when the DLL is loaded?
>
>
https://codereview.chromium.**org/13583007/<https://codereview.chromium.org/1...
>

[James Simonsen, 2013-04-16 21:17:51]

On 2013/04/14 02:02:27, Sigurður Ásgeirsson wrote:
> I'd suggest using the Vista only function as a sanity check only (use
> GetModule and GetProcAddress to retrieve them, once, not in a loop), and
> then test that your assumptions hold. If you successfully set the thread
> affinity mask to a single core, you'll be running on that particular core
> on return, or else the world will have come to an end IMHO.

Thanks for the guidance. I've done this.

[Sigurður Ásgeirsson, 2013-04-17 13:36:16]

Nice, though you'll get no metrics for Windows XP with the code as-is (I checked
and the function is not exported at XP SP2/3). Is that your intent?

https://codereview.chromium.org/13583007/diff/38001/chrome/browser/metrics/ti...
File chrome/browser/metrics/time_ticks_experiment_win.cc (right):

https://codereview.chromium.org/13583007/diff/38001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_experiment_win.cc:54: if
(!get_current_processor_func) {
since this function is unavailable on Windows XP, you'll get no metrics at all
for XP.
If you're good with that, then this is fine, but somehow I don't think that was
your intent?

https://codereview.chromium.org/13583007/diff/38001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_experiment_win.cc:87:
SetThreadAffinityMask(GetCurrentThread(), 1 << current_core);
This function can fail and a failure in this function is significant to your
code, check the return value. See also below.

https://codereview.chromium.org/13583007/diff/38001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_experiment_win.cc:88: if (!did_change_cores &&
My earlier comment on this code was to the effect that I believe it's an
inviolate post-condition of SetThreadAffinityMask, that upon *successful* return
of the function, you'll be running on one of the cores you specified. 

Witness:
http://msdn.microsoft.com/en-ca/library/windows/desktop/ms686247(v=vs.85).aspx
"If the new thread affinity mask does not specify the processor that is
currently running the thread, the thread is rescheduled on one of the allowable
processors."

So, instead of checking the current core explicitly, you may assume that you're
running on the one you specified. Since it's a "the world's coming to an end"
condition if you're not (a system API has violated it's post-conditions), it
might be appropriate to CHECK or DCHECK here if the function pointer is not
NULL.

[James Simonsen, 2013-04-19 01:32:34]

Okay, let's just rely on setting the affinity mask doing the right thing then.
Also, I forgot to restore it when the test is done. PTAL.

[Sigurður Ásgeirsson, 2013-04-19 12:59:16]

sweet - lgtm as far as the QPC is concerned.

However, you will find that QPC is orders of magnitude more expensive on Windows
XP than on Vista and newer, as the call goes to kernel on XP.

You may (now or later) want to add a second histogram to capture the cost of
each QPC call, perhaps by doing a few runs of 1000 or so back-to-back QPC calls,
and reporting the min runtime...
This is important, because the cost of acquiring the time is probably going to
be significant to Chrome's overall performance.

https://codereview.chromium.org/13583007/diff/44001/chrome/browser/metrics/ti...
File chrome/browser/metrics/time_ticks_experiment_win.cc (right):

https://codereview.chromium.org/13583007/diff/44001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_experiment_win.cc:80:
SetThreadAffinityMask(GetCurrentThread(), default_mask);
ah - great catch :)

[James Simonsen, 2013-04-22 17:47:09]

Darin, can I get lgtm for chrome/?

On 2013/04/19 12:59:16, Sigurður Ásgeirsson wrote:
> sweet - lgtm as far as the QPC is concerned.
> 
> However, you will find that QPC is orders of magnitude more expensive on
Windows
> XP than on Vista and newer, as the call goes to kernel on XP.
> 
> You may (now or later) want to add a second histogram to capture the cost of
> each QPC call, perhaps by doing a few runs of 1000 or so back-to-back QPC
calls,
> and reporting the min runtime...

I think that'll be covered by MinResolutionNanoseconds.

[darin (slow to review), 2013-04-22 18:25:05]

LGTM, but...

https://codereview.chromium.org/13583007/diff/44001/chrome/browser/metrics/ti...
File chrome/browser/metrics/time_ticks_experiment_win.h (right):

https://codereview.chromium.org/13583007/diff/44001/chrome/browser/metrics/ti...
chrome/browser/metrics/time_ticks_experiment_win.h:12: namespace
chrome_browser_metrics {
I'm not a fan of this style of namespace.  I think we should either use no
namespace or just a chrome:: namespace corresponding to the top-level directory.

There was some discussion about this back in 2010:
https://groups.google.com/a/chromium.org/forum/?fromgroups=#!topic/chromium-d...

More recently, I've grown increasingly convinced that the approach taken by
src/content and src/net is best.  That is, just have a namespace corresponding
to the top-level directory, and then prefix your classes for name-grouping below
that.  Avoid nested namespaces.

It looks like just the tracking_synchronization* files make use of this
namespace currently.

[James Simonsen, 2013-04-29 21:40:40]

On 2013/04/22 18:25:05, darin wrote:
> LGTM, but...
> 
>
https://codereview.chromium.org/13583007/diff/44001/chrome/browser/metrics/ti...
> File chrome/browser/metrics/time_ticks_experiment_win.h (right):
> 
>
https://codereview.chromium.org/13583007/diff/44001/chrome/browser/metrics/ti...
> chrome/browser/metrics/time_ticks_experiment_win.h:12: namespace
> chrome_browser_metrics {
> I'm not a fan of this style of namespace.  I think we should either use no
> namespace or just a chrome:: namespace corresponding to the top-level
directory.

Done.

[commit-bot: I haz the power, 2013-04-29 21:41:08]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/simonjam@chromium.org/13583007/53001

[commit-bot: I haz the power, 2013-04-29 21:47:21]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

[commit-bot: I haz the power, 2013-04-30 00:07:09]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/simonjam@chromium.org/13583007/72001

[commit-bot: I haz the power, 2013-04-30 01:17:24]

Retried try job too often on win_rel for step(s) interactive_ui_tests
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win_rel&nu...

[commit-bot: I haz the power, 2013-04-30 01:22:30]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/simonjam@chromium.org/13583007/92001

[commit-bot: I haz the power, 2013-04-30 04:09:17]

Retried try job too often on win_rel for step(s) interactive_ui_tests
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win_rel&nu...

[commit-bot: I haz the power, 2013-04-30 17:01:28]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/simonjam@chromium.org/13583007/109001

[commit-bot: I haz the power, 2013-04-30 19:46:07]

Change committed as 197431