timer.py

# Copyright (c) 2022 PaddlePaddle Authors. All Rights Reserved.
# 
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
# 
#     http://www.apache.org/licenses/LICENSE-2.0
# 
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

import timeit
import logging
from collections import OrderedDict


class Stack(object):
    """
    The stack in a Last-In/First-Out (LIFO) manner. New element is added at
    the end and an element is removed from that end.
    """

    def __init__(self):
        self.items = []

    def push(self, item):
        self.items.append(item)

    def pop(self):
        return self.items.pop()

    def is_empty(self):
        return len(self.items) == 0

    def peek(self):
        if not self.is_empty():
            return self.items[len(self.items) - 1]
        else:
            return None


class Event(object):
    """
    A Event is used to record the cost of every step and the cost of
    the total steps except skipped steps.
    """

    def __init__(self):
        self.reader_cost_averager = TimeAverager()
        self.batch_cost_averager = TimeAverager()
        self.total_samples = 0
        self.total_iters = 0
        self.skip_iter = 10
        self.reader_records = dict(max=0, min=float('inf'), total=0)
        self.batch_records = dict(max=0, min=float('inf'), total=0)
        self.speed_records = dict(max=0, min=float('inf'))
        self.reader = None
        self.need_record = True
        # The speed mode depends on the setting of num_samples, there
        # are 2 modes: steps/s(num_samples=None) or samples/s.
        self.speed_mode = 'samples/s'
        # The speed unit depends on the unit of samples that is
        # specified in step_info and only works in this speed_mode="samples/s".
        self.speed_unit = 'samples/s'

    def reset(self):
        self.reader_cost_averager.reset()
        self.batch_cost_averager.reset()

    def record_reader(self, usetime):
        self.reader_cost_averager.record(usetime)
        if self.total_iters >= self.skip_iter:
            self._update_records(usetime, self.reader_records)

    def record_batch(self, usetime, num_samples=None):
        if num_samples is None:
            self.speed_mode = "steps/s"
            self.speed_unit = "steps/s"
        self.batch_cost_averager.record(usetime, num_samples)
        self.total_iters += 1

        if self.total_iters >= self.skip_iter:
            self._update_records(usetime, self.batch_records)
            if self.speed_mode == "samples/s":
                current_speed = float(num_samples) / usetime
                self.total_samples += num_samples
            else:
                current_speed = 1.0 / usetime  # steps/s
            self._update_records(current_speed, self.speed_records)

    def _update_records(self, current_record, records):
        if current_record > records['max']:
            records['max'] = current_record
        elif current_record < records['min']:
            records['min'] = current_record
        if 'total' in records.keys():
            records['total'] += current_record

    def reader_average(self):
        return self.reader_cost_averager.get_average()

    def batch_average(self):
        return self.batch_cost_averager.get_average()

    def speed_average(self):
        if self.speed_mode == "samples/s":
            return self.batch_cost_averager.get_ips_average()
        else:
            return self.batch_cost_averager.get_step_average()

    def get_summary(self):
        if self.total_iters <= self.skip_iter:
            return {}

        reader_avg = 0
        batch_avg = 0
        speed_avg = 0

        self.total_iters -= self.skip_iter
        reader_avg = self.reader_records['total'] / float(self.total_iters)
        batch_avg = self.batch_records['total'] / float(self.total_iters)
        if self.speed_mode == "samples/s":
            speed_avg = float(self.total_samples) / self.batch_records['total']
        else:
            speed_avg = float(self.total_iters) / self.batch_records['total']

        reader_summary = dict(
            max=self.reader_records['max'],
            min=self.reader_records['min'],
            avg=reader_avg)
        batch_summary = dict(
            max=self.batch_records['max'],
            min=self.batch_records['min'],
            avg=batch_avg)
        ips_summary = dict(
            max=self.speed_records['max'],
            min=self.speed_records['min'],
            avg=speed_avg)
        reader_ratio = (reader_avg / batch_avg) * 100
        summary = dict(
            reader_summary=reader_summary,
            batch_summary=batch_summary,
            ips_summary=ips_summary,
            reader_ratio=reader_ratio)

        return summary


class Hook(object):
    """
    As the base class. All types of hooks should inherit from it.
    """

    def begin(self, benchmark):
        pass

    def end(self, benchmark):
        pass

    def before_reader(self, benchmark):
        pass

    def after_reader(self, benchmark):
        pass

    def after_step(self, benchmark):
        pass


class TimerHook(Hook):
    """
    A hook for recording real-time performance and the summary
    performance of total steps. 
    """

    def __init__(self):
        self.start_time = timeit.default_timer()
        self.start_reader = timeit.default_timer()

    def begin(self, benchmark):
        """
        Create the event for timing and initialize the start time of a step.
        This function will be called in `Profiler.start()`.
        """

        benchmark.events.push(Event())
        benchmark.current_event = benchmark.events.peek()
        self.start_time = timeit.default_timer()

    def before_reader(self, benchmark):
        """
        Initialize the start time of the dataloader. This function will be
        called at the beginning of `next` method in `_DataLoaderIterMultiProcess` or
        `_DataLoaderIterSingleProcess`.

        """

        self.start_reader = timeit.default_timer()

    def after_reader(self, benchmark):
        """
        Record the cost of dataloader for the current step. Since the skipped steps
        are 10, it will update the maximum, minimum and the total time from the step
        11 to the current step. This function will be called at the end of `next`
        method in `_DataLoaderIterMultiProcess` or `_DataLoaderIterSingleProcess`.

        """

        reader_cost = timeit.default_timer() - self.start_reader
        if (benchmark.current_event is None) or (
                not benchmark.current_event.need_record) or (reader_cost == 0):
            return
        benchmark.current_event.record_reader(reader_cost)

    def after_step(self, benchmark):
        """
        Record the cost for the current step. It will contain the cost of the loading
        data if there is a dataloader. Similar to `after_reader`, it will also update
        the maximum, minimum and the total time from the step 11 to the current step
        as well as the maximum and minimum speed of the model. This function will
        be called in `Profiler.step()`.

        """

        if (benchmark.current_event is None) or (
                not benchmark.current_event.need_record):
            return
        batch_cost = timeit.default_timer() - self.start_time
        benchmark.current_event.record_batch(batch_cost, benchmark.num_samples)
        self.start_time = timeit.default_timer()

    def end(self, benchmark):
        """
        Print the performance summary of the model and pop the current event
        from the events stack. Since there may be nested timing events, such
        as evaluation in the training process, the current event needs to be
        update to the event at the top of the stack.

        """

        if benchmark.events.is_empty():
            return
        self._print_summary(benchmark)
        benchmark.events.pop()
        benchmark.current_event = benchmark.events.peek()
        self.start_time = timeit.default_timer()

    def _print_summary(self, benchmark):
        summary = benchmark.current_event.get_summary()
        if not summary:
            return
        print('Perf Summary'.center(100, '='))
        if summary['reader_ratio'] != 0:
            print('Reader Ratio: ' + '%.3f' % (summary['reader_ratio']) + '%')
        print('Time Unit: s, IPS Unit: %s' %
              (benchmark.current_event.speed_unit))
        print('|', ''.center(15), '|', 'avg'.center(15), '|', 'max'.center(15),
              '|', 'min'.center(15), '|')
        # if DataLoader is not called, reader_summary is unnecessary.
        if summary['reader_summary']['avg'] != 0:
            self._print_stats('reader_cost', summary['reader_summary'])
        self._print_stats('batch_cost', summary['batch_summary'])
        self._print_stats('ips', summary['ips_summary'])

    def _print_stats(self, item, message_dict):
        avg_str = '%.5f' % (message_dict['avg'])
        max_str = '%.5f' % (message_dict['max'])
        min_str = '%.5f' % (message_dict['min'])
        print('|',
              item.center(15), '|',
              avg_str.center(15), '|',
              max_str.center(15), '|', min_str.center(15), '|')


class TimeAverager(object):
    """
    Record the cost of every step and count the average.
    """

    def __init__(self):
        self.reset()

    def reset(self):
        self._total_iters = 0
        self._total_time = 0
        self._total_samples = 0

    def record(self, usetime, num_samples=None):
        self._total_iters += 1
        self._total_time += usetime
        if num_samples:
            self._total_samples += num_samples

    def get_average(self):
        """
        Get the average cost of loading data or a step.
        """

        if self._total_iters == 0:
            return 0
        return self._total_time / float(self._total_iters)

    def get_ips_average(self):
        """
        Get the average throughput when speed mode is "samples/s".
        """

        if not self._total_samples or self._total_iters == 0:
            return 0
        return float(self._total_samples) / self._total_time

    def get_step_average(self):
        """
        Get the average speed when speed mode is "step/s".
        """

        if self._total_iters == 0:
            return 0
        return float(self._total_iters) / self._total_time


class Benchmark(object):
    """
    A tool for the statistics of model performance. The `before_reader`
    and `after_reader` are called in the DataLoader to count the cost
    of loading the data. The `begin`, `step` and `end` are called to
    count the cost of a step or total steps.
    """

    def __init__(self):
        self.num_samples = None
        self.hooks = OrderedDict(timer_hook=TimerHook())
        self.current_event = None
        self.events = Stack()

    def step(self, num_samples=None):
        """
        Record the statistic for the current step. It will be called in
        `Profiler.step()`.
        """

        self.num_samples = num_samples
        self.after_step()

    def step_info(self, unit):
        """
        It returns the statistic of the current step as a string. It contains
        "reader_cost", "batch_cost" and "ips".
        """

        message = ''
        reader_average = self.current_event.reader_average()
        batch_average = self.current_event.batch_average()
        if reader_average:
            message += ' reader_cost: %.5f s' % (reader_average)
        if batch_average:
            if self.current_event.speed_mode == 'steps/s':
                self.current_event.speed_unit = 'steps/s'
            else:
                self.current_event.speed_unit = unit + '/s'
            message += ' %s: %.5f s' % ('batch_cost', batch_average)
        speed_average = self.current_event.speed_average()
        if speed_average:
            message += ' ips: %.3f %s' % (speed_average,
                                          self.current_event.speed_unit)
        self.current_event.reset()
        return message

    def begin(self):
        for hook in self.hooks.values():
            hook.begin(self)

    def before_reader(self):
        for hook in self.hooks.values():
            hook.before_reader(self)

    def after_reader(self):
        for hook in self.hooks.values():
            hook.after_reader(self)

    def after_step(self):
        for hook in self.hooks.values():
            hook.after_step(self)

    def end(self):
        for hook in self.hooks.values():
            hook.end(self)

    def check_if_need_record(self, reader):
        if self.current_event is None:
            return
        if self.current_event.need_record:
            # set reader for the current event at the first iter
            if self.current_event.reader is None:
                self.current_event.reader = reader
            elif self.current_event.reader.__dict__[
                    '_dataset'] != reader.__dict__['_dataset']:
                # enter a new task but not calling beign() to record it.
                # we pause the timer until the end of new task, so that 
                # the cost of new task is not added to the current event.
                # eg. start evaluation in the training task
                self.current_event.need_record = False
        else:
            # when the new task exits, continue timing for the current event.
            if self.current_event.reader.__dict__[
                    '_dataset'] == reader.__dict__['_dataset']:
                self.current_event.need_record = True
                self.hooks['timer_hook'].start_time = timeit.default_timer()


_benchmark_ = Benchmark()


def benchmark():
    return _benchmark_