1445383 - ccache stats parser breaks with ccache 3.4.1

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[Kartikaya Gupta (email:[e-mail])]

I'm on OS X, running ccache 3.4.1. Output of `ccache -s` looks like this:

cache directory                     /Users/kats/.ccache
primary config                      /Users/kats/.ccache/ccache.conf
secondary config      (readonly)    /usr/local/Cellar/ccache/3.4.1/etc/ccache.conf
stats zero time                     Fri Mar  2 10:22:31 2018
cache hit (direct)                  1207
cache hit (preprocessed)             113
cache miss                         23657
cache hit rate                      5.28 %
called for link                      393
called for preprocessing             180
compile failed                       111
preprocessor error                   277
bad compiler arguments                 5
autoconf compile/link                409
no input file                        534
cleanups performed                   744
files in cache                      6187
cache size                           4.6 GB
max cache size                       5.0 GB


and doing ./mach build produces this near the end of the build:

 2:53.91 Failed to parse ccache stats output: stats zero time                     Fri Mar  2 10:22:31 2018

Comment 1

[Peter Simonyi]

Attachment: Bug 1445383 - update ccache stats parser for ccache 3.4 and 3.5

Review commit: https://reviewboard.mozilla.org/r/249186/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/249186/

Comment 2

[Peter Simonyi]

Comment on attachment 8983286 [details]
Bug 1445383 - update ccache stats parser for ccache 3.4 and 3.5

ccache 3.4 added the 'stats zero time' line.

The 'stats updated' line is currently in ccache master; it looks as if it's scheduled for 3.5.  It's not covered by the test because I only have 3.4.2 to copy from.

Comment 3

[Nathan Froyd [:froydnj]]

Comment on attachment 8983286 [details]
Bug 1445383 - update ccache stats parser for ccache 3.4 and 3.5

https://reviewboard.mozilla.org/r/249186/#review255468

With tests, too, thank you!

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c4cf68b6b73f
update ccache stats parser for ccache 3.4 and 3.5 r=froydnj

Comment 5

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/72b42d9da6b7
Backed out 1 changesets for Windows 2012 build bustages on a CLOSED TREE

Comment 6

[Nathan Froyd [:froydnj]]

Whoops, sorry; apparently I didn't let enough jobs finish on the try run to find out that things were going to break.

It looks like the new test falls over on Windows:

15:15:37     INFO - ================================== FAILURES ===================================
15:15:37     INFO - ____________________ TestCcacheStats.test_stats_version34 _____________________
15:15:37     INFO - self = <mozbuild.test.controller.test_ccachestats.TestCcacheStats testMethod=test_stats_version34>
15:15:37     INFO -     def test_stats_version34(self):
15:15:37     INFO -         # Test parsing 3.4 output.
15:15:37     INFO - >       stat8 = CCacheStats(self.STAT8)
15:15:37     INFO - ..\python\mozbuild\mozbuild\test\controller\test_ccachestats.py:258:
15:15:37     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
15:15:37     INFO - ..\python\mozbuild\mozbuild\controller\building.py:817: in __init__
15:15:37     INFO -     self._parse_line(line)
15:15:37     INFO - ..\python\mozbuild\mozbuild\controller\building.py:832: in _parse_line
15:15:37     INFO -     self._values[stat_key] = self._parse_value(raw_value)
15:15:37     INFO - ..\python\mozbuild\mozbuild\controller\building.py:845: in _parse_value
15:15:37     INFO -     ts = time.strptime(raw_value, '%c')
15:15:37     INFO - c:\mozilla-build\python\Lib\_strptime.py:478: in _strptime_time
15:15:37     INFO -     return _strptime(data_string, format)[0]
15:15:37     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
15:15:37     INFO - data_string = 'Sat Jun  2 15:37:10 2018', format = '%c'
15:15:37     INFO -     def _strptime(data_string, format="%a %b %d %H:%M:%S %Y"):
15:15:37     INFO -         """Return a time struct based on the input string and the format string."""
15:15:37     INFO -         global _TimeRE_cache, _regex_cache
15:15:37     INFO -         with _cache_lock:
15:15:37     INFO -             locale_time = _TimeRE_cache.locale_time
15:15:37     INFO -             if (_getlang() != locale_time.lang or
15:15:37     INFO -                 time.tzname != locale_time.tzname or
15:15:37     INFO -                 time.daylight != locale_time.daylight):
15:15:37     INFO -                 _TimeRE_cache = TimeRE()
15:15:37     INFO -                 _regex_cache.clear()
15:15:37     INFO -                 locale_time = _TimeRE_cache.locale_time
15:15:37     INFO -             if len(_regex_cache) > _CACHE_MAX_SIZE:
15:15:37     INFO -                 _regex_cache.clear()
15:15:37     INFO -             format_regex = _regex_cache.get(format)
15:15:37     INFO -             if not format_regex:
15:15:37     INFO -                 try:
15:15:37     INFO -                     format_regex = _TimeRE_cache.compile(format)
15:15:37     INFO -                 # KeyError raised when a bad format is found; can be specified as
15:15:37     INFO -                 # \\, in which case it was a stray % but with a space after it
15:15:37     INFO -                 except KeyError, err:
15:15:37     INFO -                     bad_directive = err.args[0]
15:15:37     INFO -                     if bad_directive == "\\":
15:15:37     INFO -                         bad_directive = "%"
15:15:37     INFO -                     del err
15:15:37     INFO -                     raise ValueError("'%s' is a bad directive in format '%s'" %
15:15:37     INFO -                                         (bad_directive, format))
15:15:37     INFO -                 # IndexError only occurs when the format string is "%"
15:15:37     INFO -                 except IndexError:
15:15:37     INFO -                     raise ValueError("stray %% in format '%s'" % format)
15:15:37     INFO -                 _regex_cache[format] = format_regex
15:15:37     INFO -         found = format_regex.match(data_string)
15:15:37     INFO -         if not found:
15:15:37     INFO -             raise ValueError("time data %r does not match format %r" %
15:15:37     INFO - >                            (data_string, format))
15:15:37     INFO - E           ValueError: time data u'Sat Jun  2 15:37:10 2018' does not match format u'%c'
15:15:37     INFO - c:\mozilla-build\python\Lib\_strptime.py:332: ValueError

Maybe Windows doesn't support the %c format specifier?

Comment 7

[Peter Simonyi]

Comment on attachment 8983286 [details]
Bug 1445383 - update ccache stats parser for ccache 3.4 and 3.5

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/249186/diff/1-2/

Comment 8

[Peter Simonyi]

The docs say %c is cross-platform, so it's probably not that.  Python figures out the parsing pattern for %c by calling strftime('%c') once and locating the individual components in that output.

But %c is locale-specific, so perhaps Windows 2012 has a different default or the test machine was running with a different locale than the others.  And ccache uses '%c' for its output, so that will vary between locales too.

It would probably be best to have some way of setting the current locale to something that's consistent cross-platform for this test, but I don't know enough about the build/test machines to even guess about that.  So instead, I've updated the test to generate the timestamp at runtime.  It feels a bit like cheating; let me know if you have better ideas!

Comment 9

[Nathan Froyd [:froydnj]]

Using a system-specific formatting seems reasonable to address the locale-specificity of %c.

Unfortunately, the update breaks everything:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=38b799d786c3acbab400869e21c6901aafe2ad07

It looks like `import time` is needed someplace?

Comment 10

[Peter Simonyi]

Comment on attachment 8983286 [details]
Bug 1445383 - update ccache stats parser for ccache 3.4 and 3.5

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/249186/diff/2-3/

Comment 11

[Peter Simonyi]

Ugh, sorry, I was reading my local test wrong.  Apparently the empty "Overall Summary" section at the end *doesn't* mean the tests all passed and the test failure was just buried among all the other passes.

Anyway, this should fix it.

Comment 12

[Nathan Froyd [:froydnj]]

Still failing on Windows, unfortunately:

16:22:39     INFO - ____________________ TestCcacheStats.test_stats_version34 _____________________
16:22:39     INFO - self = <mozbuild.test.controller.test_ccachestats.TestCcacheStats testMethod=test_stats_version34>
16:22:39     INFO -     def test_stats_version34(self):
16:22:39     INFO -         # Test parsing 3.4 output.
16:22:39     INFO - >       stat8 = CCacheStats(self.STAT8)
16:22:39     INFO - ..\python\mozbuild\mozbuild\test\controller\test_ccachestats.py:261:
16:22:39     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
16:22:39     INFO - ..\python\mozbuild\mozbuild\controller\building.py:817: in __init__
16:22:39     INFO -     self._parse_line(line)
16:22:39     INFO - ..\python\mozbuild\mozbuild\controller\building.py:832: in _parse_line
16:22:39     INFO -     self._values[stat_key] = self._parse_value(raw_value)
16:22:39     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
16:22:39     INFO - raw_value = '06/07/18 16:22:39'
16:22:39     INFO -     @staticmethod
16:22:39     INFO -     def _parse_value(raw_value):
16:22:39     INFO -         if raw_value[0].isalpha():
16:22:39     INFO -             # ccache calls strftime with '%c' (src/stats.c)
16:22:39     INFO -             ts = time.strptime(raw_value, '%c')
16:22:39     INFO -             return int(time.mktime(ts))
16:22:39     INFO -         value = raw_value.split()
16:22:39     INFO -         unit = ''
16:22:39     INFO -         if len(value) == 1:
16:22:39     INFO -             numeric = value[0]
16:22:39     INFO -         elif len(value) == 2:
16:22:39     INFO -             numeric, unit = value
16:22:39     INFO -         else:
16:22:39     INFO -             raise ValueError('Failed to parse ccache stats value: %s' % raw_value)
16:22:39     INFO -         if '.' in numeric:
16:22:39     INFO -             numeric = float(numeric)
16:22:39     INFO -         else:
16:22:39     INFO - >           numeric = int(numeric)
16:22:39     INFO - E           ValueError: invalid literal for int() with base 10: '06/07/18'
16:22:39     INFO - ..\python\mozbuild\mozbuild\controller\building.py:860: ValueError

Comment 13

[Peter Simonyi]

Comment on attachment 8983286 [details]
Bug 1445383 - update ccache stats parser for ccache 3.4 and 3.5

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/249186/diff/3-4/

Comment 14

[Peter Simonyi]

I see.  The date format doesn't have to start with a weekday.  I wish I could test this locally, but changing LC_TIME doesn't seem to get me different date formats.  Could you run another try for me?

Comment 15

[Nathan Froyd [:froydnj]]

(In reply to Peter Simonyi from comment #14)
> I see.  The date format doesn't have to start with a weekday.  I wish I
> could test this locally, but changing LC_TIME doesn't seem to get me
> different date formats.  Could you run another try for me?

Sure, no problem:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=4c08f28ab12c2561c91b473604d87e1f47b538ba

Comment 16

[Peter Simonyi]

That looks like success!  The failures don't seem at all related to this patch, so I think this is ready to land or at least re-review.

Comment 17

[Nathan Froyd [:froydnj]]

Looks good, thank you!

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/627722819abb
update ccache stats parser for ccache 3.4 and 3.5 r=froydnj

Comment 19

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/627722819abb

Comment 20

[Nathan Froyd [:froydnj]]

This has landed!