Added new time profiler HandlersTimeProfiler which allows per handler time profiling

[harsh8398]

Fixes #1346

Description:

• Added HandlersTimeProfiler which allows per handler time profiling
• Added test cases and updated docs

Output of the print_results() is as follows:

-----------------------------------------  -----------------------  --------------  --------------  --------------  --------------  --------------
Handler                                    Event Name                     Total(s)      Min(s)/IDX      Max(s)/IDX         Mean(s)          Std(s)
-----------------------------------------  -----------------------  --------------  --------------  --------------  --------------  --------------
run.<locals>.log_training_results          EPOCH_COMPLETED                 9.69906       None/None       None/None            None            None
run.<locals>.log_validation_results        EPOCH_COMPLETED                 1.27098       None/None       None/None            None            None
run.<locals>.log_time                      EPOCH_COMPLETED                 0.00023       None/None       None/None            None            None
run.<locals>.log_intermediate_results      EPOCH_COMPLETED           not triggered       None/None       None/None            None            None
run.<locals>.log_training_loss             ITERATION_COMPLETED             0.02946       1e-05/874     0.00028/519           3e-05           7e-05
run.<locals>.log_time                      COMPLETED                 not triggered       None/None       None/None            None            None
-----------------------------------------  -----------------------  --------------  --------------  --------------  --------------  --------------
Total                                                                     10.99972
-----------------------------------------  -----------------------  --------------  --------------  --------------  --------------  --------------
Processing took total 5.67398s [min/index: 0.00443s/937, max/index: 0.00784s/0, mean: 0.00605s, std: 0.00035s]
Dataflow took total 8.15311s [min/index: 0.00538s/936, max/index: 0.01123s/937, mean: 0.00869s, std: 0.00112s]

Check list:

• New tests are added (if a new feature is added)
• New doc strings: description and/or example code are in RST format
• Documentation is updated (if required)

I have trimmed the output in the docstrings and doc for the table to make it not break lines and look pretty.

[vfdev-5]

Thanks for the PR @harsh8398 !
This is not as simple as I thought, but I'm sure we can make it work after several iterations.

[vfdev-5]

@harsh8398 thanks for the update and pinging me. I'll try to checkout your code and play around to understand better how it works and if everything works as intended etc.

Meanwhile, if you could also test the profiler on a concrete example, e.g. examples/contrib/cifar10. For example, you can add this handler in the existing code and run it (eventually, you can reduce the number of epochs to 7 or 10) and see if everything works as intended. It would be very helpful 👍

[harsh8398]

@vfdev-5 Thanks, Okay I'll test it on cifar10 example. I did try MNIST before. Also FYI, there are some things left to do like:

• threshold for event filters
• export results to csv

There are some tests added but I think I can write some better tests for this. I'll update/add the tests at the end once the profiler code is finalized.

[vfdev-5]

Okay I'll test it on cifar10 example. I did try MNIST before

Oh, that's great ! Maybe, cifar10 checking is optional then. However, what I was thinking and which can be done in another follow-up PR, is providing a notebook with a basic training and showing usage of this class... Such that users could have a working example...

[harsh8398]

Oh, that's great ! Maybe, cifar10 checking is optional then. However, what I was thinking and which can be done in another follow-up PR, is providing a notebook with a basic training and showing usage of this class... Such that users could have a working example...

Should I open a follow up issue on that? I can work on that after this.

[vfdev-5]

Should I open a follow up issue on that? I can work on that after this.

Yes, please.

[vfdev-5]

@harsh8398 I checked the code and I have few questions and comments:

• code already works with custom events, that's pretty cool.

my code

import time
from ignite.engine import EventEnum


class BackpropEvents(EventEnum):
    OPTIM_STEP_COMPLETED = 'optim_step_completed'



def train_step(e, b):
    time.sleep(0.1)
    engine.fire_event(BackpropEvents.OPTIM_STEP_COMPLETED)


engine = Engine(train_step)

engine.register_events("a", "b")
engine.register_events(*BackpropEvents)


@engine.on(BackpropEvents.OPTIM_STEP_COMPLETED)
def function_before_backprop(engine):
    time.sleep(0.0333)


@engine.on(Events.EPOCH_STARTED)
def ep_start():
    time.sleep(0.15)

    
@engine.on(Events.EPOCH_COMPLETED)
def ep_end():
    time.sleep(0.2)

a_ev_args1 = [12, 34]

@engine.on(Events.EPOCH_COMPLETED(every=5), a_ev_args1)
def trigger_a_event(args1):
    engine.fire_event("a")

a_ev_args2 = [122, 324]
    
@engine.on("a", a_ev_args2)
def on_a_event(args2):
    print("triggered 'a' event", args2)
    time.sleep(1.0)


profiler = HandlersTimeProfiler()
profiler.attach(engine)


@engine.on(Events.EPOCH_COMPLETED(every=3) | Events.EPOCH_COMPLETED(once=1))
def print_profiling():
    profiler.print_results(profiler.get_results())

def get_data(n_iters):
    for i in range(n_iters):
        time.sleep(0.05)
        yield i

        
data = get_data(5 * 10)

engine.run(data, max_epochs=5, epoch_length=5)

print("Continue")

engine.run(data, max_epochs=10, epoch_length=5)

• I understand that below condition helps to avoid std to be Nan:

            min_index = ("None", "None")
            max_index = ("None", "None")
            mean = "None"
            std = "None"
            if len(data) > 1:

on the other hand, when we see None for triggered events, it is not obvious to understand why:

ep_start                      EPOCH_STARTED                    0.15022       None/None       None/None            None            None  
ep_end                        EPOCH_COMPLETED                  0.20028       None/None       None/None            None            None  
trigger_a_event               EPOCH_COMPLETED                    3e-05       None/None       None/None            None            None  

How about doing like that

            min_index = ("None", "None")
            max_index = ("None", "None")
            mean = "None"
            std = "None"
            if len(data) > 0:
                min_index = (round(torch.min(data).item(), 5), torch.argmin(data).item())
                max_index = (round(torch.max(data).item(), 5), torch.argmax(data).item())
                mean = round(torch.mean(data).item(), 5)
                if len(data) > 1:
                    std = round(torch.std(data).item(), 5)

I'll comment out also in the code.

[harsh8398]

@vfdev-5 I'll start with mypy, test cases and maybe some doc changes. Please let me know if there are any more improvements needed in profiler code.

[vfdev-5]

@harsh8398 Looks awesome now !
A little improvement for filtering timers and good to go.

For instance we'll keep this behaviour with thresholding of filtered handlers. In future, I think, it would be better to replace the way we wrap handlers to filter the execution, such that we could easily replace/wrap original handler inside filtering logic. Such that we could add timeit wrapper to the original handler instead of filtered. Anyway, this is something to think about.

[vfdev-5]

Thanks @harsh8398 !

[vfdev-5]

@harsh8398 could you please take a look how to fix the rendering in another PR ?

[harsh8398]

@vfdev-5 I'll have to trim it down to fix it. From my monitor:

Does sphinx allow scrollbar?

[vfdev-5]

@harsh8398 looks good with the trimming.

Does sphinx allow scrollbar?

For formula or code block I'm note sure...

[harsh8398]

@harsh8398 looks good with the trimming.

Its already trimmed actually. I think you are looking docs at lower resolution than my monitor.

[vfdev-5]

Its already trimmed actually. I think you are looking docs at lower resolution than my monitor.

That's possible. However when I zoom in/out with browser, layout remins the same. What is your screen resolution, actually ?

Btw, Python 3.5 CI is failing: https://github.com/pytorch/ignite/pull/1398/checks?check_run_id=1336007242#step:6:1091

@trsvchn could you please check how it is rendered in your case and see if we could tweak css a bit such that the text appears a bit smaller, if it needed ?

[trsvchn]

@harsh8398 looks good with the trimming.

Does sphinx allow scrollbar?

For formula or code block I'm note sure...

The same, I'm not sure...

[trsvchn]

@vfdev-5 on my dimensions: 1366x768 pixels (361x203 millimeters) and Firefox it looks as follows

With 100% zoom (no zoom)

But with 120% zoom it's okay

I'll check what we can do

[vfdev-5]

@trsvchn that's true, nice catch with 120% ! I tried that and also see the correct rendering. Maybe, we can try to make central window a bit larger and thus reduce the size of the left sidebar.

[trsvchn]

@vfdev-5 No worries, we can fix that with css tweaks, by changing font size of a code block for that class.

You can see that only example code block has changed.

[trsvchn]

Here is a test on master branch

[vfdev-5]

Looks neat ! Thanks @trsvchn