I have a test.py that runs inference on an image using weights of my Neural Network. I need to know the inference time for the model as a part of the framework I am building. The question is which time to consider when it comes to calculating time taken by the network within the framework? Do I consider the inference time of the network using the torch.cuda code below (which is in ms) or the cumilative time acquired using cProfiler for executing the test.py file (which is in seconds)?
Inside the test.py I have the following code for finding the inference time in ms:
####This code is for measuring performance such as inference time, FLOPs, Parameters etc...
summary(model, (1, 3, 256, 256))
dummy_input = torch.randn(1, 3, 256, 256).cuda()
macs, params = profile(model, inputs=(dummy_input,), verbose=0)
macs, params = clever_format([macs, params], "%.3f")
name = "SegDepthWithTwoDecoders"
print("<" * 50, name)
print("Flops:", macs)
print("Parameters:", params)
starter, ender = torch.cuda.Event(enable_timing=True), torch.cuda.Event(
enable_timing=True
)
repetitions = 300
timings = np.zeros((repetitions, 1))
for _ in range(10):
_ = model(dummy_input)
# MEASURE PERFORMANCE
with torch.no_grad():
for rep in range(repetitions):
starter.record()
_ = model(dummy_input)
ender.record()
# WAIT FOR GPU SYNC
torch.cuda.synchronize()
curr_time = starter.elapsed_time(ender)
timings[rep] = curr_time
print("time :", np.average(timings))
###This is where the code ends for measuring the performance
Which produces the following output:
=========================================================================================================
Layer (type:depth-idx) Output Shape Param #
=========================================================================================================
Sequential -- --
├─DoubleDec: 1 -- --
│ └─Decoder: 2 -- --
│ │ └─ModuleList: 3-1 -- 1,083,646
│ │ └─ModuleList: 3-2 -- 3,318
│ └─Decoder: 2 -- --
│ │ └─ModuleList: 3-3 -- 1,083,646
│ │ └─ModuleList: 3-4 -- 2,607
├─MobileNetv2: 1-1 [1, 3, 256, 256] --
│ └─Sequential: 2-1 [1, 32, 128, 128] --
│ │ └─Conv2d: 3-5 [1, 32, 128, 128] 864
│ │ └─BatchNorm2d: 3-6 [1, 32, 128, 128] 64
│ │ └─ReLU6: 3-7 [1, 32, 128, 128] --
│ └─Sequential: 2-2 [1, 16, 128, 128] --
│ │ └─InvertedResidualBlock: 3-8 [1, 16, 128, 128] 1,984
│ └─Sequential: 2-3 [1, 24, 64, 64] --
│ │ └─InvertedResidualBlock: 3-9 [1, 24, 64, 64] 5,136
│ │ └─InvertedResidualBlock: 3-10 [1, 24, 64, 64] 8,832
│ └─Sequential: 2-4 [1, 32, 32, 32] --
│ │ └─InvertedResidualBlock: 3-11 [1, 32, 32, 32] 10,000
│ │ └─InvertedResidualBlock: 3-12 [1, 32, 32, 32] 14,848
│ │ └─InvertedResidualBlock: 3-13 [1, 32, 32, 32] 14,848
│ └─Sequential: 2-5 [1, 64, 16, 16] --
│ │ └─InvertedResidualBlock: 3-14 [1, 64, 16, 16] 21,056
│ │ └─InvertedResidualBlock: 3-15 [1, 64, 16, 16] 54,272
│ │ └─InvertedResidualBlock: 3-16 [1, 64, 16, 16] 54,272
│ │ └─InvertedResidualBlock: 3-17 [1, 64, 16, 16] 54,272
│ └─Sequential: 2-6 [1, 96, 16, 16] --
│ │ └─InvertedResidualBlock: 3-18 [1, 96, 16, 16] 66,624
│ │ └─InvertedResidualBlock: 3-19 [1, 96, 16, 16] 118,272
│ │ └─InvertedResidualBlock: 3-20 [1, 96, 16, 16] 118,272
│ └─Sequential: 2-7 [1, 160, 8, 8] --
│ │ └─InvertedResidualBlock: 3-21 [1, 160, 8, 8] 155,264
│ │ └─InvertedResidualBlock: 3-22 [1, 160, 8, 8] 320,000
│ │ └─InvertedResidualBlock: 3-23 [1, 160, 8, 8] 320,000
│ └─Sequential: 2-8 [1, 320, 8, 8] --
│ │ └─InvertedResidualBlock: 3-24 [1, 320, 8, 8] 473,920
├─DoubleDec: 1-2 [1, 42, 32, 32] --
│ └─Decoder: 2-9 [1, 42, 32, 32] --
│ └─Decoder: 2-10 [1, 33, 32, 32] --
=========================================================================================================
Total params: 3,986,017
Trainable params: 3,986,017
Non-trainable params: 0
Total mult-adds (G): 1.84
=========================================================================================================
Input size (MB): 0.79
Forward/backward pass size (MB): 255.35
Params size (MB): 15.94
Estimated Total Size (MB): 272.08
=========================================================================================================
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< SegDepthWithTwoDecoders
Flops: 1.924G
Parameters: 3.986M
time : 13.261571423212688
However, when I use the cProfiler on test.py and visualize the .dat file using snakeviz I get the following output (cropped to first few results) when sorted using cumilative time. The time taken for test.py to execute is 13.91 seconds. While the forward pass in the last entry below shows a 1.95 seconds time.
ncalls tottime percall cumtime percall filename:lineno(function)
1513/1 0.04356 0.04356 13.91 13.91 ~:0(<built-in method builtins.exec>)
1 0.01504 0.01504 13.91 13.91 test_orig.py:1(<module>)
1 0.000362 0.000362 5.392 5.392 serialization.py:502(load)
1 0.01159 0.01159 5.391 5.391 ~:0(<method 'load' of '_pickle.Unpickler' objects>)
1 0.000129 0.000129 5.391 5.391 serialization.py:836(_load)
256 0.001342 5.242e-06 5.242 0.02048 serialization.py:848(persistent_load)
256 0.02492 9.736e-05 5.24 0.02047 serialization.py:841(load_tensor)
256 0.000617 2.41e-06 5.215 0.02037 serialization.py:173(default_restore_location)
256 0.000807 3.152e-06 5.214 0.02037 serialization.py:149(_cuda_deserialize)
9026 5.177 0.0005735 5.178 0.0005737 ~:0(<built-in method __new__ of type object at 0x560298777b40>)
256 0.002574 1.005e-05 5.168 0.02019 _utils.py:48(_cuda)
256 0.000713 2.785e-06 5.141 0.02008 __init__.py:601(_lazy_new)
60528/312 0.2104 0.0006744 3.268 0.01048 module.py:1096(_call_impl)
5616/312 0.09013 0.0002889 3.259 0.01044 container.py:139(forward)
1282/8 0.009451 0.001181 2.598 0.3248 <frozen importlib._bootstrap>:966(_find_and_load)
1276/8 0.007926 0.0009907 2.598 0.3247 <frozen importlib._bootstrap>:936(_find_and_load_unlocked)
1217/8 0.008436 0.001054 2.596 0.3245 <frozen importlib._bootstrap>:651(_load_unlocked)
1108/8 0.004488 0.000561 2.596 0.3245 <frozen importlib._bootstrap_external>:672(exec_module)
1577/8 0.001239 0.0001549 2.594 0.3243 <frozen importlib._bootstrap>:211(_call_with_frames_removed)
2 0.000127 6.35e-05 2.494 1.247 dataloader.py:517(__next__)
2 3.5e-05 1.75e-05 2.493 1.247 dataloader.py:1156(_next_data)
5 0.000165 3.3e-05 2.48 0.496 connection.py:897(wait)
5 2.479 0.4958 2.479 0.4958 ~:0(<method 'poll' of 'select.poll' objects>)
5 0.00013 2.6e-05 2.479 0.4959 selectors.py:365(select)
1 8.4e-05 8.4e-05 2.443 2.443 queues.py:91(get)
1 1.4e-05 1.4e-05 2.443 2.443 dataloader.py:977(_try_get_data)
1 9e-06 9e-06 2.443 2.443 dataloader.py:1123(_get_data)
1 1.6e-05 1.6e-05 2.432 2.432 connection.py:413(_poll)
1 6e-06 6e-06 2.432 2.432 connection.py:253(poll)
312 0.002597 8.324e-06 1.951 0.006254 my_model.py:160(forward)
624 0.04902 7.856e-05 1.942 0.003113 my_model.py:144(forward)