Bug 947256 - Report ccache hit rate at the end of the build; r=gps
authorTing-Yu Lin <tlin@mozilla.com>
Wed, 30 Jul 2014 02:23:00 -0700
changeset 219502 56b1d9be395b9b53f7516944370e0be95bb8e4bf
parent 219501 2c4ad23ccbc83606fd9bb1e1a2a24dade0d3dc36
child 219503 fdabd8fe19c019169aeba40265613211922699b8
push id3979
push userraliiev@mozilla.com
push dateMon, 13 Oct 2014 16:35:44 +0000
treeherdermozilla-beta@30f2cc610691 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersgps
bugs947256
milestone34.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 947256 - Report ccache hit rate at the end of the build; r=gps This patch add a line at the end of the build like follows: ccache (direct) hit rate: 98.7%; (preprocessed) hit rate: 0.5%; miss rate: 0.8%
python/moz.build
python/mozbuild/mozbuild/controller/building.py
python/mozbuild/mozbuild/mach_commands.py
python/mozbuild/mozbuild/test/controller/test_ccachestats.py
--- a/python/moz.build
+++ b/python/moz.build
@@ -28,16 +28,17 @@ PYTHON_UNIT_TESTS += [
     'mozbuild/mozbuild/test/backend/test_android_eclipse.py',
     'mozbuild/mozbuild/test/backend/test_configenvironment.py',
     'mozbuild/mozbuild/test/backend/test_recursivemake.py',
     'mozbuild/mozbuild/test/backend/test_visualstudio.py',
     'mozbuild/mozbuild/test/common.py',
     'mozbuild/mozbuild/test/compilation/__init__.py',
     'mozbuild/mozbuild/test/compilation/test_warnings.py',
     'mozbuild/mozbuild/test/controller/__init__.py',
+    'mozbuild/mozbuild/test/controller/test_ccachestats.py',
     'mozbuild/mozbuild/test/controller/test_clobber.py',
     'mozbuild/mozbuild/test/frontend/__init__.py',
     'mozbuild/mozbuild/test/frontend/test_emitter.py',
     'mozbuild/mozbuild/test/frontend/test_namespaces.py',
     'mozbuild/mozbuild/test/frontend/test_reader.py',
     'mozbuild/mozbuild/test/frontend/test_sandbox.py',
     'mozbuild/mozbuild/test/frontend/test_sandbox_symbols.py',
     'mozbuild/mozbuild/test/test_base.py',
--- a/python/mozbuild/mozbuild/controller/building.py
+++ b/python/mozbuild/mozbuild/controller/building.py
@@ -3,18 +3,20 @@
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 from __future__ import unicode_literals
 
 import getpass
 import json
 import logging
 import os
+import subprocess
 import sys
 import time
+import which
 
 from collections import (
     namedtuple,
     OrderedDict,
 )
 
 try:
     import psutil
@@ -427,16 +429,202 @@ class BuildMonitor(MozbuildObject):
 
         message = prefix + ' - Wall time: {duration:.0f}s; ' \
             'CPU: {cpu_percent:.0f}%; ' \
             'Read bytes: {io_read_bytes}; Write bytes: {io_write_bytes}; ' \
             'Read time: {io_read_time}; Write time: {io_write_time}'
 
         self.log(logging.WARNING, m_type, params, message)
 
+    def ccache_stats(self):
+        ccache_stats = None
+
+        try:
+            ccache = which.which('ccache')
+            output = subprocess.check_output([ccache, '-s'])
+            ccache_stats = CCacheStats(output)
+        except which.WhichError:
+            pass
+        except ValueError as e:
+            self.log(logging.WARNING, 'ccache', {'msg': str(e)}, '{msg}')
+
+        return ccache_stats
+
+
+class CCacheStats(object):
+    """Holds statistics from ccache.
+
+    Instances can be subtracted from each other to obtain differences.
+    print() or str() the object to show a ``ccache -s`` like output
+    of the captured stats.
+
+    """
+    STATS_KEYS = [
+        # (key, description)
+        # Refer to stats.c in ccache project for all the descriptions.
+        ('cache_hit_direct', 'cache hit (direct)'),
+        ('cache_hit_preprocessed', 'cache hit (preprocessed)'),
+        ('cache_miss', 'cache miss'),
+        ('link', 'called for link'),
+        ('preprocessing', 'called for preprocessing'),
+        ('multiple', 'multiple source files'),
+        ('stdout', 'compiler produced stdout'),
+        ('no_output', 'compiler produced no output'),
+        ('empty_output', 'compiler produced empty output'),
+        ('failed', 'compile failed'),
+        ('error', 'ccache internal error'),
+        ('preprocessor_error', 'preprocessor error'),
+        ('cant_use_pch', "can't use precompiled header"),
+        ('compiler_missing', "couldn't find the compiler"),
+        ('cache_file_missing', 'cache file missing'),
+        ('bad_args', 'bad compiler arguments'),
+        ('unsupported_lang', 'unsupported source language'),
+        ('compiler_check_failed', 'compiler check failed'),
+        ('autoconf', 'autoconf compile/link'),
+        ('unsupported_compiler_option', 'unsupported compiler option'),
+        ('out_stdout', 'output to stdout'),
+        ('out_device', 'output to a non-regular file'),
+        ('no_input', 'no input file'),
+        ('bad_extra_file', 'error hashing extra file'),
+        ('cache_files', 'files in cache'),
+        ('cache_size', 'cache size'),
+        ('cache_max_size', 'max cache size'),
+    ]
+
+    DIRECTORY_DESCRIPTION = "cache directory"
+    ABSOLUTE_KEYS = {'cache_max_size'}
+    FORMAT_KEYS = {'cache_size', 'cache_max_size'}
+
+    GiB = 1024 ** 3
+    MiB = 1024 ** 2
+    KiB = 1024
+
+    def __init__(self, output=None):
+        """Construct an instance from the output of ccache -s."""
+        self._values = {}
+        self.cache_dir = ""
+
+        if not output:
+            return
+
+        for line in output.splitlines():
+            line = line.strip()
+            if line:
+                self._parse_line(line)
+
+    def _parse_line(self, line):
+        if line.startswith(self.DIRECTORY_DESCRIPTION):
+            self.cache_dir = self._strip_prefix(line, self.DIRECTORY_DESCRIPTION)
+            return
+
+        for stat_key, stat_description in self.STATS_KEYS:
+            if line.startswith(stat_description):
+                raw_value = self._strip_prefix(line, stat_description)
+                self._values[stat_key] = self._parse_value(raw_value)
+                break
+        else:
+            raise ValueError('Failed to parse ccache stats output: %s' % line)
+
+    @staticmethod
+    def _strip_prefix(line, prefix):
+        return line[len(prefix):].strip() if line.startswith(prefix) else line
+
+    @staticmethod
+    def _parse_value(raw_value):
+        value = raw_value.split()
+        unit = ''
+        if len(value) == 1:
+            numeric = value[0]
+        elif len(value) == 2:
+            numeric, unit = value
+        else:
+            raise ValueError('Failed to parse ccache stats value: %s' % raw_value)
+
+        if '.' in numeric:
+            numeric = float(numeric)
+        else:
+            numeric = int(numeric)
+
+        if unit in ('GB', 'Gbytes'):
+            unit = CCacheStats.GiB
+        elif unit in ('MB', 'Mbytes'):
+            unit = CCacheStats.MiB
+        elif unit in ('KB', 'Kbytes'):
+            unit = CCacheStats.KiB
+        else:
+            unit = 1
+
+        return int(numeric * unit)
+
+    def hit_rate_message(self):
+        return 'ccache (direct) hit rate: {:.1%}; (preprocessed) hit rate: {:.1%}; miss rate: {:.1%}'.format(*self.hit_rates())
+
+    def hit_rates(self):
+        direct = self._values['cache_hit_direct']
+        preprocessed = self._values['cache_hit_preprocessed']
+        miss = self._values['cache_miss']
+        total = float(direct + preprocessed + miss)
+
+        if total > 0:
+            direct /= total
+            preprocessed /= total
+            miss /= total
+
+        return (direct, preprocessed, miss)
+
+    def __sub__(self, other):
+        result = CCacheStats()
+        result.cache_dir = self.cache_dir
+
+        for k, prefix in self.STATS_KEYS:
+            if k not in self._values and k not in other._values:
+                continue
+
+            our_value = self._values.get(k, 0)
+            other_value = other._values.get(k, 0)
+
+            if k in self.ABSOLUTE_KEYS:
+                result._values[k] = our_value
+            else:
+                result._values[k] = our_value - other_value
+
+        return result
+
+    def __str__(self):
+        LEFT_ALIGN = 34
+        lines = []
+
+        if self.cache_dir:
+            lines.append('%s%s' % (self.DIRECTORY_DESCRIPTION.ljust(LEFT_ALIGN),
+                                   self.cache_dir))
+
+        for stat_key, stat_description in self.STATS_KEYS:
+            if stat_key not in self._values:
+                continue
+
+            value = self._values[stat_key]
+
+            if stat_key in self.FORMAT_KEYS:
+                value = '%15s' % self._format_value(value)
+            else:
+                value = '%8u' % value
+
+            lines.append('%s%s' % (stat_description.ljust(LEFT_ALIGN), value))
+
+        return '\n'.join(lines)
+
+    @staticmethod
+    def _format_value(v):
+        if v > CCacheStats.GiB:
+            return '%.1f Gbytes' % (float(v) / CCacheStats.GiB)
+        elif v > CCacheStats.MiB:
+            return '%.1f Mbytes' % (float(v) / CCacheStats.MiB)
+        else:
+            return '%.1f Kbytes' % (float(v) / CCacheStats.KiB)
+
 
 class BuildDriver(MozbuildObject):
     """Provides a high-level API for build actions."""
 
     def install_tests(self, remove=True):
         """Install test files (through manifest)."""
 
         if self.is_clobber_needed():
--- a/python/mozbuild/mozbuild/mach_commands.py
+++ b/python/mozbuild/mozbuild/mach_commands.py
@@ -280,16 +280,17 @@ class Build(MachCommandBase):
         from mozbuild.controller.building import BuildMonitor
         from mozbuild.util import resolve_target_to_make
 
         self.log_manager.register_structured_logger(logging.getLogger('mozbuild'))
 
         warnings_path = self._get_state_filename('warnings.json')
         monitor = self._spawn(BuildMonitor)
         monitor.init(warnings_path)
+        ccache_start = monitor.ccache_stats()
 
         with BuildOutputManager(self.log_manager, monitor) as output:
             monitor.start()
 
             if what:
                 top_make = os.path.join(self.topobjdir, 'Makefile')
                 if not os.path.exists(top_make):
                     print('Your tree has not been configured yet. Please run '
@@ -387,16 +388,23 @@ class Build(MachCommandBase):
                     '{count} compiler warnings present.')
 
             monitor.finish(record_usage=status==0)
 
         high_finder, finder_percent = monitor.have_high_finder_usage()
         if high_finder:
             print(FINDER_SLOW_MESSAGE % finder_percent)
 
+        ccache_end = monitor.ccache_stats()
+
+        if ccache_start and ccache_end:
+            ccache_diff = ccache_end - ccache_start
+            self.log(logging.INFO, 'ccache',
+                     {'msg': ccache_diff.hit_rate_message()}, "{msg}")
+
         if monitor.elapsed > 300:
             # Display a notification when the build completes.
             # This could probably be uplifted into the mach core or at least
             # into a helper API. It is here as an experimentation to see how it
             # is received.
             try:
                 if sys.platform.startswith('darwin'):
                     notifier = which.which('terminal-notifier')
new file mode 100644
--- /dev/null
+++ b/python/mozbuild/mozbuild/test/controller/test_ccachestats.py
@@ -0,0 +1,78 @@
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+
+from __future__ import unicode_literals
+
+import unittest
+
+from mozunit import main
+
+from mozbuild.controller.building import CCacheStats
+
+
+class TestCcacheStats(unittest.TestCase):
+    STAT_GARBAGE = """A garbage line which should be failed to parse"""
+
+    STAT0 = """
+    cache directory                     /home/tlin/.ccache
+    cache hit (direct)                     0
+    cache hit (preprocessed)               0
+    cache miss                             0
+    files in cache                         0
+    cache size                             0 Kbytes
+    max cache size                      16.0 Gbytes"""
+
+    STAT1 = """
+    cache directory                     /home/tlin/.ccache
+    cache hit (direct)                   100
+    cache hit (preprocessed)             200
+    cache miss                          2500
+    called for link                      180
+    called for preprocessing               6
+    compile failed                        11
+    preprocessor error                     3
+    bad compiler arguments                 6
+    unsupported source language            9
+    autoconf compile/link                 60
+    unsupported compiler option            2
+    no input file                         21
+    files in cache                      7344
+    cache size                           1.9 Gbytes
+    max cache size                      16.0 Gbytes"""
+
+    STAT2 = """
+    cache directory                     /home/tlin/.ccache
+    cache hit (direct)                  1900
+    cache hit (preprocessed)             300
+    cache miss                          2600
+    called for link                      361
+    called for preprocessing              12
+    compile failed                        22
+    preprocessor error                     6
+    bad compiler arguments                12
+    unsupported source language           18
+    autoconf compile/link                120
+    unsupported compiler option            4
+    no input file                         48
+    files in cache                      7392
+    cache size                           2.0 Gbytes
+    max cache size                      16.0 Gbytes"""
+
+    def test_parse_garbage_stats_message(self):
+        self.assertRaises(ValueError, CCacheStats, self.STAT_GARBAGE)
+
+    def test_parse_zero_stats_message(self):
+        stats = CCacheStats(self.STAT0)
+        self.assertEqual(stats.cache_dir, "/home/tlin/.ccache")
+        self.assertEqual(stats.hit_rates(), (0, 0, 0))
+
+    def test_hit_rate_of_diff_stats(self):
+        stats1 = CCacheStats(self.STAT1)
+        stats2 = CCacheStats(self.STAT2)
+        stats_diff = stats2 - stats1
+        self.assertEqual(stats_diff.hit_rates(), (0.9, 0.05, 0.05))
+
+
+if __name__ == '__main__':
+    main()