HiQ Tracing Tutorial¶
Latency tracing is always enabled as long as global HiQ status is on. Other than latency, HiQ provides memory, disk I/O, network I/O, and Exception tracing out of the box.
Global HiQ Status¶
Global HiQ status is a cross-process boolean value that decide if HiQ running in the current machine is enabled or not. There are two functions to get and set the global HiQ status. You can get them from:
from hiq.hiq_utils import get_global_hiq_status, set_global_hiq_status
The following is the demo code:
1 2 3 4 5 6 7 8 9 10 | from hiq.hiq_utils import get_global_hiq_status, set_global_hiq_status if __name__ == "__main__": set_global_hiq_status(True) b = get_global_hiq_status() print(b) set_global_hiq_status(False) b = get_global_hiq_status() print(b) |
Run it and you will get:
ℹ️ python examples/hiq_global_status/demo.py
😇 set global hiq to True
True
😇 set global hiq to False
False
If global HiQ status is False, all the HiQ in the machine is disabled. If it is True, you can call disable()
to disable a specific HiQ Object. This is so-called dynamic tracing
.
Note
We assume global HiQ status is already set to True in this tutorial.
Normally you don’t have to call them directly. Instead you use context manager hiq.HiQStatusContext()
to make sure the HiQ status is on or off.
Tip
hiq.HiQStatusContext() is the best practice to use whenever possible.
Dynamic Tracing¶
HiQ tracing is dynamic, which means you can enable and disable it as needed. The following is a simple example.
You can disable and enable HiQ tracing at run time.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 | import hiq import time def run_main(): # create an `hiq.HiQLatency` object and HiQ is enabled by default with hiq.HiQStatusContext(): driver = hiq.HiQLatency( hiq_table_or_path=[ ["main", "", "main", "main"], ["main", "", "func1", "func1"], ["main", "", "func2", "func2"], ] ) print("*" * 20, "HiQ is enabled", "*" * 20) start = time.time() hiq.mod("main").main() print(f"{time.time()-start} second") driver.show() # disable HiQ in `driver` print("*" * 20, "disable HiQ", "*" * 20) driver.disable_hiq(reset_trace=True) start = time.time() hiq.mod("main").main() print(f"{time.time()-start} second") driver.show() # enable HiQ in `driver` again print("*" * 20, "re-enable HiQ", "*" * 20) driver.enable_hiq(reset_trace=True) start = time.time() hiq.mod("main").main() print(f"{time.time()-start} second") driver.show() if __name__ == "__main__": run_main() |
With this code above, we disable and enable HiQ tracing, and run the main()
function. The result is like:
The environment variable HIQ_STATUS_CACHED
decide if the result is cached. If it is enabled, the result will be cached for 5 seconds
.
Metrics Customization¶
HiQ supports metrics customization. You can choose to trace different metrics in HiQ tree.
ExtraMetrics¶
Now HiQ supports 3 types of customized metrics: ExtraMetrics.FILE
, ExtraMetrics.FUNC
, ExtraMetrics.ARGS
. You can pass them in a set object to extra_metrics
in the constructor like below. And of course, different metrics have different latency overheads, which you can find in HiQ tree as well.
Target Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 | import time def func1(x, y): time.sleep(1.5) func2(y) def func2(y): time.sleep(2.5) def main(x, y): func1(x, y) if __name__ == "__main__": main(1, 2) |
Driver Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 | import hiq import os from hiq.constants import ExtraMetrics here = os.path.dirname(os.path.realpath(__file__)) def run_main(): with hiq.HiQStatusContext(debug=False): driver1 = hiq.HiQLatency( f"{here}/hiq.conf", extra_metrics={ExtraMetrics.FILE}, ) hiq.mod("main").main(1, 2) driver1.show() driver1.disable_hiq() driver2 = hiq.HiQLatency( f"{here}/hiq.conf", extra_metrics={ExtraMetrics.FUNC}, ) hiq.mod("main").main(1, 2) driver2.show() driver2.disable_hiq() driver3 = hiq.HiQLatency( f"{here}/hiq.conf", extra_metrics={ExtraMetrics.ARGS}, ) hiq.mod("main").main(1, 2) driver3.show() driver3.disable_hiq() driver4 = hiq.HiQLatency( f"{here}/hiq.conf", extra_metrics={ ExtraMetrics.FILE, ExtraMetrics.FUNC, ExtraMetrics.ARGS, }, ) hiq.mod("main").main(1, 2) driver4.show() if __name__ == "__main__": run_main() |
Note
If we create one more driver for the same target, we need to disable the previous driver by calling driver.disable_hiq(), otherwise an exception will be raised.
Run this file and the output will be like:
ℹ️ python examples/extra/simple/main_driver.py
[2021-11-07 19:46:47.464262 - 19:46:51.476240] [100.00%] 🟢_root_time(4.0120)
[OH:38767us]
[2021-11-07 19:46:47.464262 - 19:46:51.476240] [100.00%] l___main(4.0120) ({'file': 'examples/extra/simple/main_driver.py:10'})
[2021-11-07 19:46:47.466069 - 19:46:51.476229] [ 99.95%] l___func1(4.0102) ({'file': 'examples/extra/simple/main.py:14'})
[2021-11-07 19:46:48.973780 - 19:46:51.476187] [ 62.37%] l___func2(2.5024) ({'file': 'examples/extra/simple/main.py:6'})
[2021-11-07 19:46:51.478223 - 19:46:55.488515] [100.00%] 🟢_root_time(4.0103)
[OH:6217us]
[2021-11-07 19:46:51.478223 - 19:46:55.488515] [100.00%] l___main(4.0103) ({'function': 'run_main'})
[2021-11-07 19:46:51.480468 - 19:46:55.488504] [ 99.94%] l___func1(4.0080) ({'function': 'main'})
[2021-11-07 19:46:52.985900 - 19:46:55.488467] [ 62.40%] l___func2(2.5026) ({'function': 'func1'})
[2021-11-07 19:46:55.490225 - 19:46:59.494639] [100.00%] 🟢_root_time(4.0044)
[OH:212us]
[2021-11-07 19:46:55.490225 - 19:46:59.494639] [100.00%] l___main(4.0044) ({'args': '[int](1),[int](2)'})
[2021-11-07 19:46:55.490282 - 19:46:59.494629] [100.00%] l___func1(4.0043) ({'args': '[int](1),[int](2)'})
[2021-11-07 19:46:56.992013 - 19:46:59.494591] [ 62.50%] l___func2(2.5026) ({'args': '[int](2)'})
[2021-11-07 19:46:59.496759 - 19:47:03.512220] [100.00%] 🟢_root_time(4.0155)
[OH:9936us]
[2021-11-07 19:46:59.496759 - 19:47:03.512220] [100.00%] l___main(4.0155) ({'args': '[int](1),[int](2)', 'file': 'examples/extra/simple/main_driver.py:28', 'function': 'run_main'})
[2021-11-07 19:46:59.500252 - 19:47:03.512210] [ 99.91%] l___func1(4.0120) ({'args': '[int](1),[int](2)', 'file': 'examples/extra/simple/main.py:14', 'function': 'main'})
[2021-11-07 19:47:01.010409 - 19:47:03.512170] [ 62.30%] l___func2(2.5018) ({'args': '[int](2)', 'file': 'examples/extra/simple/main.py:6', 'function': 'func1'})
We can see when we enable ExtraMetrics.FILE
, the file path and number name will be attached to the tree node. When we enable ExtraMetrics.FUNC
, the caller function name will be attached to the tree node. When we enable ExtraMetrics.ARGS
, the function argument type and value will be attached to the tree node. If we enable all of them, all the information will be attached, but we got the largest latency overhead.
Complex Data Type¶
Target Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 | import time def func1(x, y, df): time.sleep(1.5) func2(y) def func2(y): time.sleep(2.5) def main(x, y, df, lst, bytes, *args, **kwargs): func1(x, y, df) |
Driver Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 | import hiq import os import numpy as np import pandas as pd import torch from hiq.constants import ExtraMetrics here = os.path.dirname(os.path.realpath(__file__)) def run_main(): a = torch.rand(2000, 3) b = np.random.rand(3, 2000) df = pd.DataFrame(np.random.randint(0, 100, size=(100, 4)), columns=list("ABCD")) series = pd.date_range(start="2016-01-01", end="2020-12-31", freq="D") with hiq.HiQStatusContext(debug=False): with hiq.HiQLatency( f"{here}/hiq.conf", extra_metrics={ExtraMetrics.ARGS}, ) as driver: hiq.mod("main").main( a, b, df, [1, 2, 3], b"abc", st=set({5, 6, 7}), dt={"a": 1}, pd_time=series, ) driver.show() if __name__ == "__main__": run_main() |
Run this file and the output will be like:
ℹ️ python examples/extra/complex/main_driver.py
[2021-11-07 19:51:05.408034 - 19:51:09.412475] [100.00%] 🟢_root_time(4.0044)
[OH:260us]
[2021-11-07 19:51:05.408034 - 19:51:09.412475] [100.00%] l___main(4.0044) ({'args': '[tensor](torch.Size([2000, 3])),[ndarry]((3, 2000)),[pandas]((100, 4)),[list<int>](3),[bytes](3)', 'kwargs': '{\'st\': \'[set](3)\', \'dt\': "[dict]([\'a\'])", \'pd_time\': \'[DatetimeIndex](1827)\'}'})
[2021-11-07 19:51:05.408108 - 19:51:09.412463] [100.00%] l___func1(4.0044) ({'args': '[tensor](torch.Size([2000, 3])),[ndarry]((3, 2000)),[pandas]((100, 4))'})
[2021-11-07 19:51:06.909852 - 19:51:09.412425] [ 62.49%] l___func2(2.5026) ({'args': '[ndarry]((3, 2000))'})
HiQ can handle all python built in types and third-party module’ types including Pytorch tensor, Numpy NDArray, Pandas DataFrame and Series.
Large Data Structure¶
Tracing large data structure like arrays could be a performance killer. It will take a lot of CPU and some memory as well, and slow down the program. So this section is only recommended for use case where performance requirement is not that critical.
By default, HiQ trace the type and value of function arguments. For composite data structures, it traces the type and size
instead of value. But sometimes, you may really need to know the data no matter how big it is. In this case, you can pass your own function arguments handler When creating HiQ Tracing Object.
With the same target code as above, we can have this driver code to save large data to hard disk:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 | import os import pickle import hiq import numpy as np import pandas as pd import torch from hiq.constants import ExtraMetrics from hiq.utils import write_file here = os.path.dirname(os.path.realpath(__file__)) def large_data_processor(x, func_name=None) -> str: if func_name == "__main": if isinstance(x, tuple): write_file("/tmp/main.args.log", x[2].to_string(), append=True) elif isinstance(x, dict): with open("/tmp/main.args.pkl", "wb") as handle: pickle.dump(x, handle, protocol=pickle.HIGHEST_PROTOCOL) return "..." else: return hiq.hiq_utils.func_args_handler(x, func_name) def run_main(): a = torch.rand(2000, 3) b = np.random.rand(3, 2000) df = pd.DataFrame(np.random.randint(0, 100, size=(100, 4)), columns=list("ABCD")) series = pd.date_range(start="2016-01-01", end="2020-12-31", freq="D") with hiq.HiQStatusContext(debug=False): with hiq.HiQLatency( f"{here}/hiq.conf", extra_metrics={ExtraMetrics.ARGS}, func_args_handler=large_data_processor, ) as driver: hiq.mod("main").main( a, b, df, [1, 2, 3], b"abc", st=set({5, 6, 7}), dt={"a": 1}, pd_time=series, ) driver.show() if __name__ == "__main__": run_main() |
Run the code and we’ll get something like:
[2021-11-08 00:17:23.378755 - 00:17:27.383362] [100.00%] 🟢_root_time(4.0046)
[OH:8027us]
[2021-11-08 00:17:23.378755 - 00:17:27.383362] [100.00%] l___main(4.0046) ({'args': '...', 'kwargs': '...'})
[2021-11-08 00:17:23.378954 - 00:17:27.383350] [ 99.99%] l___func1(4.0044) ({'args': '[tensor](torch.Size([2000, 3])),[ndarry]((3, 2000)),[pandas]((100, 4))'})
[2021-11-08 00:17:24.880710 - 00:17:27.383292] [ 62.49%] l___func2(2.5026) ({'args': '[ndarry]((3, 2000))'})
The argument df
has been saved into a file. To verify it:
ℹ️ cat /tmp/main.args.log |wc -l
100
The output 100 matches the row number 100 in line 29.
The entire kwargs
has been pickled into /tmp/main.args.pkl
. To verify the values:
>>> import pickle
>>> x = pickle.load(open('/tmp/main.args.pkl','rb'))
>>> x
{'st': {5, 6, 7}, 'dt': {'a': 1}, 'pd_time': DatetimeIndex(['2016-01-01', '2016-01-02', '2016-01-03', '2016-01-04',
'2016-01-05', '2016-01-06', '2016-01-07', '2016-01-08',
'2016-01-09', '2016-01-10',
...
'2020-12-22', '2020-12-23', '2020-12-24', '2020-12-25',
'2020-12-26', '2020-12-27', '2020-12-28', '2020-12-29',
'2020-12-30', '2020-12-31'],
dtype='datetime64[ns]', length=1827, freq='D')}
Memory Tracing¶
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 | import hiq import os from hiq.constants import KEY_MEMORY, FORMAT_DATETIME here = os.path.dirname(os.path.realpath(__file__)) def run_main(): with hiq.HiQStatusContext(): driver = hiq.HiQMemory(f"{here}/hiq.conf") hiq.mod("main").main() driver.get_metrics(metrics_key=KEY_MEMORY)[0].show() if __name__ == "__main__": run_main() |
Output:
ℹ️ python examples/memory/main_driver.py
func1
func2
[ 19.457 - 19.461] [100.00%] 🟢_root_get_memory_mb(0.0039)
[ 19.457 - 19.461] [100.00%] l___main(0.0039)
The memory here means RSS memory. From the example above, we can see the memory is increased from 19.457MB to 19.461MB before and after the main function invocation. And the two functions func1
and func2
don’t consume extra memory because we don’t see them in the output. The reason why we don’t see them is they are zero span node
.
Timestamp With Non-latency Metrics¶
Unlike the latency metrics, memory is not related to time, so we don’t see any timestamp in above output, which is not convenient for our debugging. For non-latency metrics, to get timestamp in the output, we should add attach_timestamp=True
in hiq.HiQMemory
’s constructor.
Note
This works for all non-latency metrics like memory, disk I/O, network I/O etc.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 | import hiq import os from hiq.constants import KEY_MEMORY, FORMAT_DATETIME here = os.path.dirname(os.path.realpath(__file__)) def run_main(): with hiq.HiQStatusContext(): driver = hiq.HiQMemory(f"{here}/hiq.conf", attach_timestamp=True) hiq.mod("main").main() driver.get_metrics(metrics_key=KEY_MEMORY)[0].show() if __name__ == "__main__": run_main() |
The result becomes:
$ python examples/memory/main_driver2.py
func1
func2
[ 219.582 - 219.590] [100.00%] 🟢_root_get_memory_mb(0.0078)
[1636877696.769 - 1636877700.774] [ 219.582 - 219.590] [100.00%] l___main(0.0078)
We can change the date time format by specify time_format=FORMAT_DATETIME
in the show
function. The new driver code is like:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 | import hiq import os from hiq.constants import KEY_MEMORY, FORMAT_DATETIME here = os.path.dirname(os.path.realpath(__file__)) def run_main(): with hiq.HiQStatusContext(): driver = hiq.HiQMemory(f"{here}/hiq.conf", attach_timestamp=True) hiq.mod("main").main() driver.get_metrics(metrics_key=KEY_MEMORY)[0].show(time_format=FORMAT_DATETIME) if __name__ == "__main__": run_main() |
In the new output below, we can see the datetime time format has changed:
$ python examples/memory/main_driver3.py
func1
func2
[ 219.500 - 219.508] [100.00%] 🟢_root_get_memory_mb(0.0078)
[2021-11-14 08:18:02.419058 - 08:18:06.423343] [ 219.500 - 219.508] [100.00%] l___main(0.0078)
Disk I/O Tracing¶
Target Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 | import os, time from hiq.utils import execute_cmd, random_str def create_and_read(k=102400): time.sleep(2) _100mb_file = "/tmp/" + random_str() + ".bin" if not os.path.exists(_100mb_file): execute_cmd( f"dd if=/dev/zero of={_100mb_file} bs=1024 count={k}", verbose=False ) with open(_100mb_file) as f: s = f.read() print(f"🥰 read file size: {len(s)} bytes") def fun1(): time.sleep(2) create_and_read(k=3) fun2() def fun2(): time.sleep(1) create_and_read(k=2) def main(): fun1() if __name__ == "__main__": main() |
Driver Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 | import hiq from hiq.constants import * def run_main(): with hiq.HiQStatusContext(): driver = hiq.HiQLatency( hiq_table_or_path=[ ["main", "", "main", "main"], ["main", "", "create_and_read", "cr"], ["main", "", "fun1", "f1"], ["main", "", "fun2", "f2"], ], extra_hiq_table=[TAU_TABLE_DIO_RD], ) hiq.mod("main").main() driver.show() if __name__ == "__main__": run_main() |
Run the driver code and get the output:
ℹ️ python hiq/examples/io_disk/main_driver.py
🥰 read file size: 3072 bytes
🥰 read file size: 2048 bytes
[2021-11-03 22:45:37.416571 - 22:45:44.432328] [100.00%] 🟢_root_time(7.0158)
[OH:552us]
[2021-11-03 22:45:37.416571 - 22:45:44.432328] [100.00%] l___main(7.0158)
[2021-11-03 22:45:37.416641 - 22:45:44.432315] [100.00%] l___f1(7.0157)
[2021-11-03 22:45:39.418850 - 22:45:41.424977] [ 28.59%] |___cr(2.0061)
[2021-11-03 22:45:41.424852 - 22:45:41.424904] [ 0.00%] | l___dio_r(0.0001)
[2021-11-03 22:45:41.425046 - 22:45:44.432301] [ 42.86%] l___f2(3.0073)
[2021-11-03 22:45:42.426265 - 22:45:44.432281] [ 28.59%] l___cr(2.0060)
[2021-11-03 22:45:44.432160 - 22:45:44.432212] [ 0.00%] l___dio_r(0.0001)
[ 0.000 - 5120.000] [100.00%] 🟢_root_get_io_bytes_r(5120.0000)
[ 0.000 - 5120.000] [100.00%] l___main(5120.0000)
[ 0.000 - 5120.000] [100.00%] l___f1(5120.0000)
[ 0.000 - 3072.000] [ 60.00%] |___cr(3072.0000)
[ 0.000 - 3072.000] [ 60.00%] | l___dio_r(3072.0000)
[3072.000 - 5120.000] [ 40.00%] l___f2(2048.0000)
[3072.000 - 5120.000] [ 40.00%] l___cr(2048.0000)
[3072.000 - 5120.000] [ 40.00%] l___dio_r(2048.0000)
System I/O Tracing¶
The following target code creates a 3KB file in fun1()
and a 2KB file in fun2()
and then use os.read
, which invokes linux system call read()
, to read 50 bytes through file descriptor. HiQ can trace the I/O traffic of linux system call read()
and write()
.
Target Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 | import os, time from hiq.utils import execute_cmd, random_str def create_and_read(k=102400): time.sleep(2) _100mb_file = "/tmp/" + random_str() + ".bin" if not os.path.exists(_100mb_file): execute_cmd( f"dd if=/dev/zero of={_100mb_file} bs=1024 count={k}", verbose=False ) fd = os.open(_100mb_file, os.O_RDONLY) readBytes = os.read(fd, 50) os.close(fd) def fun1(): time.sleep(2) create_and_read(k=3) fun2() def fun2(): time.sleep(1) create_and_read(k=2) def main(): fun1() if __name__ == "__main__": main() |
We can trace the system I/O by adding HIQ_TABLE_SIO_RD
for read or HIQ_TABLE_SIO_WT
for write. The following is the driver code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 | import hiq from hiq.constants import HIQ_TABLE_SIO_RD def run_main(): with hiq.HiQStatusContext(): driver = hiq.HiQLatency( hiq_table_or_path=[ ["main", "", "main", "main"], ["main", "", "create_and_read", "cr"], ["main", "", "fun1", "f1"], ["main", "", "fun2", "f2"], ], extra_hiq_table=[HIQ_TABLE_SIO_RD], ) hiq.mod("main").main() driver.show() if __name__ == "__main__": run_main() |
Run the driver code and get the output:
ℹ️ python examples/io_sys/main_driver.py
[2021-11-04 02:56:27.995306 - 02:56:35.008258] [100.00%] 🟢_root_time(7.0130)
[OH:896us]
[2021-11-04 02:56:27.995306 - 02:56:35.008258] [100.00%] l___main(7.0130)
[2021-11-04 02:56:27.995369 - 02:56:35.008245] [100.00%] l___f1(7.0129)
[2021-11-04 02:56:29.997583 - 02:56:32.002374] [ 28.59%] |___cr(2.0048)
[2021-11-04 02:56:32.001401 - 02:56:32.001539] [ 0.00%] | |___sio_r(0.0001)
[2021-11-04 02:56:32.002117 - 02:56:32.002136] [ 0.00%] | |___sio_r(0.0000)
[2021-11-04 02:56:32.002340 - 02:56:32.002354] [ 0.00%] | l___sio_r(0.0000)
[2021-11-04 02:56:32.002420 - 02:56:35.008234] [ 42.86%] l___f2(3.0058)
[2021-11-04 02:56:33.003664 - 02:56:35.008218] [ 28.58%] l___cr(2.0046)
[2021-11-04 02:56:35.007247 - 02:56:35.007400] [ 0.00%] |___sio_r(0.0002)
[2021-11-04 02:56:35.007963 - 02:56:35.007983] [ 0.00%] |___sio_r(0.0000)
[2021-11-04 02:56:35.008180 - 02:56:35.008200] [ 0.00%] l___sio_r(0.0000)
[0.000 - 100.000] [100.00%] 🟢_root_get_sio_bytes_r(100.0000)
[0.000 - 100.000] [100.00%] l___main(100.0000)
[0.000 - 100.000] [100.00%] l___f1(100.0000)
[0.000 - 50.000] [ 50.00%] |___cr(50.0000)
[0.000 - 50.000] [ 50.00%] | l___sio_r(50.0000)
[50.000 - 100.000] [ 50.00%] l___f2(50.0000)
[50.000 - 100.000] [ 50.00%] l___cr(50.0000)
[50.000 - 100.000] [ 50.00%] l___sio_r(50.0000)
Network I/O Tracing¶
Target Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 | import os import time from hiq.utils import execute_cmd, random_str, download_from_http count = 0 here = os.path.dirname(os.path.realpath(__file__)) def create_and_read(k=102400): _100mb_file = "/tmp/" + random_str() + ".bin" if not os.path.exists(_100mb_file): execute_cmd(f"dd if=/dev/zero of={_100mb_file} bs=1024 count={k}") with open(_100mb_file) as f: s = f.read() print(f"🥰 file size: {len(s)}, {s[len(s) // 2 - 1]}") def func1(): global count if count == 5: create_and_read(1024 * 10) count += 1 return elif count > 5: return count += 1 func4() # print("func1") def func2(): # print("func2") time.sleep(0.1) func1() def func3(): # print("func3") time.sleep(0.12) func2() def func4(): # print("func4") if count == 0: create_and_read(1024 * 50) if count == 3: download_from_http( "https://www.gardeningknowhow.com/wp-content/uploads/2017/07/hardwood-tree.jpg", "/tmp/tree.jpg", ) time.sleep(0.2) func2() func3() def func5(): time.sleep(0.24) # print("let func5 raise exception") # raise Exception("o") def fit(model="awesome_model", data="awesome_data"): print(f"{data=},{model=}") time.sleep(0.35) func4() def predict(model="awesome_model", data="awesome_data"): print(f"{data=},{model=}") time.sleep(0.16) func5() def main(): fit(model="awesome_model_1", data="awesome_data_1") predict(model="awesome_model_2", data="awesome_data_2") if __name__ == "__main__": main() |
In func4()
, when global variable count
is equal to 3, it will download an image from the internet.
The image size is 199602 bytes as displayed below:
-rw-rw-r-- 1 ubuntu ubuntu 199602 May 13 2018 hardwood-tree.jpg
Driver Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 | import hiq from hiq.constants import * def run_main(): with hiq.HiQStatusContext(): driver = hiq.HiQLatency( hiq_table_or_path=[ ["main", "", "main", "main"], ["main", "", "func1", "func1"], ["main", "", "func2", "func2"], ["main", "", "func3", "func3"], ["main", "", "func4", "func4"], ["main", "", "func5", "func5"], ], extra_hiq_table=[TAU_TABLE_NIO_GET], ) hiq.mod("main").main() driver.show() if __name__ == "__main__": run_main() |
Notice at line 15, we added a new line to track network ingress I/O. To track the egress traffic, you just need to replace TAU_TABLE_NIO_GET
with TAU_TABLE_NIO_WRT
.
Output:
[2021-11-03 08:25:53.510876 - 08:25:57.561308] [100.00%] 🟢_root_time(4.0504)
[OH:2074us]
[2021-11-03 08:25:53.510876 - 08:25:57.561308] [100.00%] l___main(4.0504)
[2021-11-03 08:25:53.861402 - 08:25:57.160576] [ 81.45%] |___func4(3.2992)
[2021-11-03 08:25:54.183760 - 08:25:56.940055] [ 68.05%] | |___func2(2.7563)
[2021-11-03 08:25:54.283967 - 08:25:56.940045] [ 65.58%] | | l___func1(2.6561)
[2021-11-03 08:25:54.284018 - 08:25:56.940032] [ 65.57%] | | l___func4(2.6560)
[2021-11-03 08:25:54.484393 - 08:25:56.719469] [ 55.18%] | | |___func2(2.2351)
[2021-11-03 08:25:54.584729 - 08:25:56.719449] [ 52.70%] | | | l___func1(2.1347)
[2021-11-03 08:25:54.584799 - 08:25:56.719430] [ 52.70%] | | | l___func4(2.1346)
[2021-11-03 08:25:54.785170 - 08:25:56.498725] [ 42.31%] | | | |___func2(1.7136)
[2021-11-03 08:25:54.885402 - 08:25:56.498709] [ 39.83%] | | | | l___func1(1.6133)
[2021-11-03 08:25:54.885453 - 08:25:56.498696] [ 39.83%] | | | | l___func4(1.6132)
[2021-11-03 08:25:54.885522 - 08:25:54.906254] [ 0.51%] | | | | |___nio_get(0.0207)
[2021-11-03 08:25:55.106743 - 08:25:56.278137] [ 28.92%] | | | | |___func2(1.1714)
[2021-11-03 08:25:55.206995 - 08:25:56.278122] [ 26.44%] | | | | | l___func1(1.0711)
[2021-11-03 08:25:55.207054 - 08:25:56.278107] [ 26.44%] | | | | | l___func4(1.0711)
[2021-11-03 08:25:55.407383 - 08:25:56.057437] [ 16.05%] | | | | | |___func2(0.6501)
[2021-11-03 08:25:55.507616 - 08:25:56.057420] [ 13.57%] | | | | | | l___func1(0.5498)
[2021-11-03 08:25:55.507676 - 08:25:56.057403] [ 13.57%] | | | | | | l___func4(0.5497)
[2021-11-03 08:25:55.708037 - 08:25:55.836658] [ 3.18%] | | | | | | |___func2(0.1286)
[2021-11-03 08:25:55.808240 - 08:25:55.836573] [ 0.70%] | | | | | | | l___func1(0.0283)
[2021-11-03 08:25:55.836824 - 08:25:56.057387] [ 5.45%] | | | | | | l___func3(0.2206)
[2021-11-03 08:25:55.957082 - 08:25:56.057372] [ 2.48%] | | | | | | l___func2(0.1003)
[2021-11-03 08:25:56.057324 - 08:25:56.057343] [ 0.00%] | | | | | | l___func1(0.0000)
[2021-11-03 08:25:56.057490 - 08:25:56.278093] [ 5.45%] | | | | | l___func3(0.2206)
[2021-11-03 08:25:56.177766 - 08:25:56.278078] [ 2.48%] | | | | | l___func2(0.1003)
[2021-11-03 08:25:56.278022 - 08:25:56.278050] [ 0.00%] | | | | | l___func1(0.0000)
[2021-11-03 08:25:56.278194 - 08:25:56.498680] [ 5.44%] | | | | l___func3(0.2205)
[2021-11-03 08:25:56.398421 - 08:25:56.498667] [ 2.47%] | | | | l___func2(0.1002)
[2021-11-03 08:25:56.498626 - 08:25:56.498643] [ 0.00%] | | | | l___func1(0.0000)
[2021-11-03 08:25:56.498771 - 08:25:56.719408] [ 5.45%] | | | l___func3(0.2206)
[2021-11-03 08:25:56.619078 - 08:25:56.719386] [ 2.48%] | | | l___func2(0.1003)
[2021-11-03 08:25:56.719326 - 08:25:56.719350] [ 0.00%] | | | l___func1(0.0000)
[2021-11-03 08:25:56.719543 - 08:25:56.940020] [ 5.44%] | | l___func3(0.2205)
[2021-11-03 08:25:56.839789 - 08:25:56.940008] [ 2.47%] | | l___func2(0.1002)
[2021-11-03 08:25:56.939970 - 08:25:56.939986] [ 0.00%] | | l___func1(0.0000)
[2021-11-03 08:25:56.940103 - 08:25:57.160563] [ 5.44%] | l___func3(0.2205)
[2021-11-03 08:25:57.060336 - 08:25:57.160552] [ 2.47%] | l___func2(0.1002)
[2021-11-03 08:25:57.160520 - 08:25:57.160533] [ 0.00%] | l___func1(0.0000)
[2021-11-03 08:25:57.320969 - 08:25:57.561265] [ 5.93%] l___func5(0.2403)
[ 0.000 - 199602.000] [100.00%] 🟢_root_get_nio_bytes_r(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___main(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func4(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func2(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func1(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func4(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func2(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func1(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func4(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func2(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func1(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___func4(199602.0000)
[ 0.000 - 199602.000] [100.00%] l___nio_get(199602.0000)
We can see from the HiQ tree, network I/O get function nio_get()
is called by called func4
and the network traffic is 199602 bytes, and the downloading took 20.7 milliseconds.
Exception Tracing¶
HiQ provides exception tracing out of the box. By default, HiQ will populate the exception out until you catch it.
Target Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 | import time def func1(): time.sleep(1.5) print("func1") func2() def func2(): time.sleep(2.5) print("func2") raise ValueError("an_exception") func3() def func3(): time.sleep(2.5) print("func3") def main(): func1() if __name__ == "__main__": main() |
Driver Code 1:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 | import hiq import os here = os.path.dirname(os.path.realpath(__file__)) def run_main(): with hiq.HiQStatusContext(): driver = hiq.HiQLatency(f"{here}/hiq.conf") try: hiq.mod("main").main() except Exception as e: print(e) driver.show() if __name__ == "__main__": run_main() |
Output:
ℹ️ python examples/exception/main_driver.py
func1
func2
an_exception
[2021-11-03 17:17:03.547380 - 17:17:07.551894] [100.00%] 🟢_root_time(4.0045)
[OH:121us]
[2021-11-03 17:17:03.547380 - 17:17:07.551894] [100.00%] l___main(4.0045) ({'exception_summary': ValueError('an_exception')})
[2021-11-03 17:17:03.547442 - 17:17:07.551874] [100.00%] l___func1(4.0044) ({'exception_summary': ValueError('an_exception')})
[2021-11-03 17:17:05.049179 - 17:17:07.551824] [ 62.50%] l___func2(2.5026) ({'exception_summary': ValueError('an_exception')})
You can also specify fast_fail=False
when creating the HiQ object like hiq.HiQLatency
, so that the exception will be silent and you get a concise HiQ tree.
Driver Code 2:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 | import hiq import os here = os.path.dirname(os.path.realpath(__file__)) def run_main(): with hiq.HiQStatusContext(): driver = hiq.HiQLatency(f"{here}/hiq.conf", fast_fail=False) hiq.mod("main").main() driver.show() if __name__ == "__main__": run_main() |
Output:
ℹ️ python examples/exception/main_driver2.py
func1
func2
[2021-11-03 17:22:18.648640 - 17:22:22.652281] [100.00%] 🟢_root_time(4.0036)
[OH:193us]
[2021-11-03 17:22:18.648640 - 17:22:22.652281] [100.00%] l___main(4.0036)
[2021-11-03 17:22:18.648686 - 17:22:22.652268] [100.00%] l___func1(4.0036)
[2021-11-03 17:22:20.150435 - 17:22:22.652231] [ 62.49%] l___func2(2.5018)
Multiple Tracing¶
When HiQ is enabled and we call the target code more than one times, we will get multiple tracing results.
Target Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 | import os import time from hiq.utils import download_from_http, execute_cmd, random_str count = 0 def create_and_read(k=102400): _100mb_file = "/tmp/" + random_str() + ".bin" if not os.path.exists(_100mb_file): execute_cmd( f"dd if=/dev/zero of={_100mb_file} bs=1024 count={k}", verbose=False ) with open(_100mb_file) as f: s = f.read() def func1(): global count if count == 5: create_and_read(1024 * 10) count += 1 return elif count > 5: return count += 1 func4() def func2(): time.sleep(0.1) func1() def func3(): time.sleep(0.12) func2() def func4(): if count == 0: create_and_read(1024 * 5) if count == 3: download_from_http( "https://www.gardeningknowhow.com/wp-content/uploads/2017/07/hardwood-tree.jpg", "/tmp/tree.jpg", ) time.sleep(0.2) func2() func3() def func5(): time.sleep(0.24) def fit(model="awesome_model", data="awesome_data"): time.sleep(0.35) func4() def predict(model="awesome_model", data="awesome_data"): time.sleep(0.16) func5() def main(): for i in range(4): fit(data={}, model=[i]) predict(model=f"awesome_model_{i}", data=i) if __name__ == "__main__": main() |
Driver Code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 | import os import hiq import traceback, sys from hiq.hiq_utils import get_global_hiq_status, set_global_hiq_status, HiQIdGenerator from unittest.mock import MagicMock here = os.path.dirname(os.path.realpath(__file__)) def run_main(): _g_driver_original = get_global_hiq_status() set_global_hiq_status(True) driver = hiq.HiQLatency( hiq_table_or_path=f"{here}/hiq.conf", max_hiq_size=4, ) for i in range(3): driver.get_tau_id = HiQIdGenerator() try: hiq.mod("main").fit(data={}, model=[i]) except Exception as e: traceback.print_exc(file=sys.stdout) driver.show(show_key=True) driver.disable_hiq() print("-^" * 20, "disable HiQ", "-^" * 20) hiq.mod("main").fit(data={}, model=[i]) set_global_hiq_status(_g_driver_original) if __name__ == "__main__": run_main() |
From line 1 to 5: import necessary modules and functions. get_global_hiq_status
and set_global_hiq_status
are used to get and set the global hiq status. If the status is on, HiQ will function; if off, HiQ will stop working but you can still run the program.
Line 7: get the current directory path.
Line 10: define a function called run_main
.
Line 11 to 12: back up the original HiQ status and set it to True
Line 13 to 16: create an object driver
which has a type of class hiq.HiQLatency
. hiq.HiQLatency
is for latency tracking. We have hiq.HiQMemory
to track both latency and memory. Users can also inherit hiq.HiQSimple
to customize the metrics they want to track, but that is an advanced topics. For now, in this case, we just need hiq.HiQLatency
to track latency.
Line 18 to 20: run the target code main.py’s function fit()
for 3 times.
Line 21: print the latency traces as trees.
Line 23: disable HiQ
Line 25: run target code main.py’s function fit()
once again.
Line 26: set the global hiq status back to what it was before this run
Run the driver code, you can get result like:
ℹ️ python examples/multi-tracing/main_driver.py
😇 set global hiq to True
🔑 k0: 0, 🗝 k1: time
[2021-11-03 19:38:38.528194 - 19:38:41.750020] [100.00%] 🟢_root_time(3.2218)
[OH:3242us]
[2021-11-03 19:38:38.528194 - 19:38:41.750020] [100.00%] l___f4(3.2218)
[2021-11-03 19:38:38.745514 - 19:38:41.529168] [ 86.40%] |___f2(2.7837)
[2021-11-03 19:38:38.845949 - 19:38:41.529151] [ 83.28%] | l___f1(2.6832)
[2021-11-03 19:38:38.846075 - 19:38:41.529131] [ 83.28%] | l___f4(2.6831)
[2021-11-03 19:38:39.046535 - 19:38:41.308501] [ 70.21%] | |___f2(2.2620)
[2021-11-03 19:38:39.146943 - 19:38:41.308482] [ 67.09%] | | l___f1(2.1615)
[2021-11-03 19:38:39.147045 - 19:38:41.308462] [ 67.09%] | | l___f4(2.1614)
[2021-11-03 19:38:39.347496 - 19:38:41.087750] [ 54.01%] | | |___f2(1.7403)
[2021-11-03 19:38:39.447848 - 19:38:41.087731] [ 50.90%] | | | l___f1(1.6399)
[2021-11-03 19:38:39.447920 - 19:38:41.087709] [ 50.90%] | | | l___f4(1.6398)
[2021-11-03 19:38:39.694061 - 19:38:40.866945] [ 36.40%] | | | |___f2(1.1729)
[2021-11-03 19:38:39.794394 - 19:38:40.866924] [ 33.29%] | | | | l___f1(1.0725)
[2021-11-03 19:38:39.794470 - 19:38:40.866904] [ 33.29%] | | | | l___f4(1.0724)
[2021-11-03 19:38:39.994862 - 19:38:40.646264] [ 20.22%] | | | | |___f2(0.6514)
[2021-11-03 19:38:40.095094 - 19:38:40.646241] [ 17.11%] | | | | | l___f1(0.5511)
[2021-11-03 19:38:40.095146 - 19:38:40.646216] [ 17.10%] | | | | | l___f4(0.5511)
[2021-11-03 19:38:40.295571 - 19:38:40.425075] [ 4.02%] | | | | | |___f2(0.1295)
[2021-11-03 19:38:40.395917 - 19:38:40.424979] [ 0.90%] | | | | | | l___f1(0.0291)
[2021-11-03 19:38:40.425275 - 19:38:40.646194] [ 6.86%] | | | | | l___f3(0.2209)
[2021-11-03 19:38:40.545736 - 19:38:40.646169] [ 3.12%] | | | | | l___f2(0.1004)
[2021-11-03 19:38:40.646097 - 19:38:40.646127] [ 0.00%] | | | | | l___f1(0.0000)
[2021-11-03 19:38:40.646342 - 19:38:40.866882] [ 6.85%] | | | | l___f3(0.2205)
[2021-11-03 19:38:40.766563 - 19:38:40.866861] [ 3.11%] | | | | l___f2(0.1003)
[2021-11-03 19:38:40.866809 - 19:38:40.866829] [ 0.00%] | | | | l___f1(0.0000)
[2021-11-03 19:38:40.867007 - 19:38:41.087684] [ 6.85%] | | | l___f3(0.2207)
[2021-11-03 19:38:40.987283 - 19:38:41.087656] [ 3.12%] | | | l___f2(0.1004)
[2021-11-03 19:38:41.087594 - 19:38:41.087622] [ 0.00%] | | | l___f1(0.0000)
[2021-11-03 19:38:41.087820 - 19:38:41.308437] [ 6.85%] | | l___f3(0.2206)
[2021-11-03 19:38:41.208148 - 19:38:41.308417] [ 3.11%] | | l___f2(0.1003)
[2021-11-03 19:38:41.308362 - 19:38:41.308385] [ 0.00%] | | l___f1(0.0000)
[2021-11-03 19:38:41.308562 - 19:38:41.529113] [ 6.85%] | l___f3(0.2206)
[2021-11-03 19:38:41.428829 - 19:38:41.529091] [ 3.11%] | l___f2(0.1003)
[2021-11-03 19:38:41.529046 - 19:38:41.529062] [ 0.00%] | l___f1(0.0000)
[2021-11-03 19:38:41.529225 - 19:38:41.749990] [ 6.85%] l___f3(0.2208)
[2021-11-03 19:38:41.649575 - 19:38:41.749968] [ 3.12%] l___f2(0.1004)
[2021-11-03 19:38:41.749906 - 19:38:41.749931] [ 0.00%] l___f1(0.0000)
🔑 k0: 1, 🗝 k1: time
[2021-11-03 19:38:42.101156 - 19:38:42.622677] [100.00%] 🟢_root_time(0.5215)
[OH:546us]
[2021-11-03 19:38:42.101156 - 19:38:42.622677] [100.00%] l___f4(0.5215)
[2021-11-03 19:38:42.301611 - 19:38:42.401940] [ 19.24%] |___f2(0.1003)
[2021-11-03 19:38:42.401887 - 19:38:42.401910] [ 0.00%] | l___f1(0.0000)
[2021-11-03 19:38:42.402009 - 19:38:42.622652] [ 42.31%] l___f3(0.2206)
[2021-11-03 19:38:42.522245 - 19:38:42.622633] [ 19.25%] l___f2(0.1004)
[2021-11-03 19:38:42.622575 - 19:38:42.622600] [ 0.00%] l___f1(0.0000)
🔑 k0: 2, 🗝 k1: time
[2021-11-03 19:38:42.973617 - 19:38:43.495121] [100.00%] 🟢_root_time(0.5215)
[OH:527us]
[2021-11-03 19:38:42.973617 - 19:38:43.495121] [100.00%] l___f4(0.5215)
[2021-11-03 19:38:43.173992 - 19:38:43.274265] [ 19.23%] |___f2(0.1003)
[2021-11-03 19:38:43.274217 - 19:38:43.274235] [ 0.00%] | l___f1(0.0000)
[2021-11-03 19:38:43.274325 - 19:38:43.495096] [ 42.33%] l___f3(0.2208)
[2021-11-03 19:38:43.394686 - 19:38:43.495076] [ 19.25%] l___f2(0.1004)
[2021-11-03 19:38:43.495018 - 19:38:43.495043] [ 0.00%] l___f1(0.0000)
-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^ disable HiQ -^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^-^
😇 set global hiq to True
Note at line 16 above, we mocked driver.get_tau_id
’s return value. In production or a more realistic setup, you don’t have to do the mock, because HiQLatency
will generate id for every instantiation automatically. The driver code will be like this:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 | import os import hiq import traceback, sys from hiq.hiq_utils import ( HiQIdGenerator, HiQStatusContext, ) here = os.path.dirname(os.path.realpath(__file__)) def run_main(): with HiQStatusContext(): for i in range(3): with hiq.HiQLatency(hiq_table_or_path=f"{here}/hiq.conf") as driver: try: hiq.mod("main").fit(data={}, model=[i]) except Exception as e: traceback.print_exc(file=sys.stdout) finally: driver.show(show_key=True) if __name__ == "__main__": run_main() |
Tip
Using HiQLatency in a with statement is recommended, because this way you don’t have to manually call driver.disable_hiq().
Run the code and the result is like:
ℹ️ python examples/multi-tracing/main_driver_real.py
🔑 k0: 16363948034575320, 🗝 k1: time
[2021-11-08 18:06:43.809487 - 18:06:47.034452] [100.00%] 🟢_root_time(3.2250)
[OH:1309us]
[2021-11-08 18:06:43.809487 - 18:06:47.034452] [100.00%] l___f4(3.2250)
[2021-11-08 18:06:44.028084 - 18:06:46.813921] [ 86.38%] |___f2(2.7858)
[2021-11-08 18:06:44.128282 - 18:06:46.813914] [ 83.28%] | l___f1(2.6856)
[2021-11-08 18:06:44.128330 - 18:06:46.813906] [ 83.27%] | l___f4(2.6856)
[2021-11-08 18:06:44.328635 - 18:06:46.593395] [ 70.23%] | |___f2(2.2648)
[2021-11-08 18:06:44.428813 - 18:06:46.593385] [ 67.12%] | | l___f1(2.1646)
[2021-11-08 18:06:44.428851 - 18:06:46.593379] [ 67.12%] | | l___f4(2.1645)
[2021-11-08 18:06:44.629144 - 18:06:46.372974] [ 54.07%] | | |___f2(1.7438)
[2021-11-08 18:06:44.729428 - 18:06:46.372967] [ 50.96%] | | | l___f1(1.6435)
[2021-11-08 18:06:44.729487 - 18:06:46.372956] [ 50.96%] | | | l___f4(1.6435)
[2021-11-08 18:06:44.972807 - 18:06:46.152537] [ 36.58%] | | | |___f2(1.1797)
[2021-11-08 18:06:45.073035 - 18:06:46.152529] [ 33.47%] | | | | l___f1(1.0795)
[2021-11-08 18:06:45.073101 - 18:06:46.152517] [ 33.47%] | | | | l___f4(1.0794)
[2021-11-08 18:06:45.273425 - 18:06:45.931942] [ 20.42%] | | | | |___f2(0.6585)
[2021-11-08 18:06:45.373683 - 18:06:45.931931] [ 17.31%] | | | | | l___f1(0.5582)
[2021-11-08 18:06:45.373748 - 18:06:45.931919] [ 17.31%] | | | | | l___f4(0.5582)
[2021-11-08 18:06:45.574080 - 18:06:45.711033] [ 4.25%] | | | | | |___f2(0.1370)
[2021-11-08 18:06:45.674290 - 18:06:45.710935] [ 1.14%] | | | | | | l___f1(0.0366)
[2021-11-08 18:06:45.711257 - 18:06:45.931909] [ 6.84%] | | | | | l___f3(0.2207)
[2021-11-08 18:06:45.831599 - 18:06:45.931898] [ 3.11%] | | | | | l___f2(0.1003)
[2021-11-08 18:06:45.931852 - 18:06:45.931873] [ 0.00%] | | | | | l___f1(0.0000)
[2021-11-08 18:06:45.931988 - 18:06:46.152507] [ 6.84%] | | | | l___f3(0.2205)
[2021-11-08 18:06:46.052282 - 18:06:46.152497] [ 3.11%] | | | | l___f2(0.1002)
[2021-11-08 18:06:46.152464 - 18:06:46.152475] [ 0.00%] | | | | l___f1(0.0000)
[2021-11-08 18:06:46.152581 - 18:06:46.372947] [ 6.83%] | | | l___f3(0.2204)
[2021-11-08 18:06:46.272759 - 18:06:46.372938] [ 3.11%] | | | l___f2(0.1002)
[2021-11-08 18:06:46.372916 - 18:06:46.372924] [ 0.00%] | | | l___f1(0.0000)
[2021-11-08 18:06:46.373011 - 18:06:46.593367] [ 6.83%] | | l___f3(0.2204)
[2021-11-08 18:06:46.493184 - 18:06:46.593360] [ 3.11%] | | l___f2(0.1002)
[2021-11-08 18:06:46.593342 - 18:06:46.593349] [ 0.00%] | | l___f1(0.0000)
[2021-11-08 18:06:46.593431 - 18:06:46.813896] [ 6.84%] | l___f3(0.2205)
[2021-11-08 18:06:46.713605 - 18:06:46.813889] [ 3.11%] | l___f2(0.1003)
[2021-11-08 18:06:46.813858 - 18:06:46.813873] [ 0.00%] | l___f1(0.0000)
[2021-11-08 18:06:46.813971 - 18:06:47.034441] [ 6.84%] l___f3(0.2205)
[2021-11-08 18:06:46.934184 - 18:06:47.034435] [ 3.11%] l___f2(0.1003)
[2021-11-08 18:06:47.034407 - 18:06:47.034421] [ 0.00%] l___f1(0.0000)
🔑 k0: 16363948070358521, 🗝 k1: time
[2021-11-08 18:06:47.387733 - 18:06:47.908781] [100.00%] 🟢_root_time(0.5210)
[OH:229us]
[2021-11-08 18:06:47.387733 - 18:06:47.908781] [100.00%] l___f4(0.5210)
[2021-11-08 18:06:47.588017 - 18:06:47.688221] [ 19.23%] |___f2(0.1002)
[2021-11-08 18:06:47.688196 - 18:06:47.688206] [ 0.00%] | l___f1(0.0000)
[2021-11-08 18:06:47.688260 - 18:06:47.908773] [ 42.32%] l___f3(0.2205)
[2021-11-08 18:06:47.808428 - 18:06:47.908765] [ 19.26%] l___f2(0.1003)
[2021-11-08 18:06:47.908721 - 18:06:47.908746] [ 0.00%] l___f1(0.0000)
🔑 k0: 16363948079093882, 🗝 k1: time
[2021-11-08 18:06:48.261303 - 18:06:48.782447] [100.00%] 🟢_root_time(0.5211)
[OH:238us]
[2021-11-08 18:06:48.261303 - 18:06:48.782447] [100.00%] l___f4(0.5211)
[2021-11-08 18:06:48.461619 - 18:06:48.561838] [ 19.23%] |___f2(0.1002)
[2021-11-08 18:06:48.561810 - 18:06:48.561821] [ 0.00%] | l___f1(0.0000)
[2021-11-08 18:06:48.561881 - 18:06:48.782439] [ 42.32%] l___f3(0.2206)
[2021-11-08 18:06:48.682091 - 18:06:48.782432] [ 19.25%] l___f2(0.1003)
[2021-11-08 18:06:48.782395 - 18:06:48.782414] [ 0.00%] l___f1(0.0000)
Another way to replace the mock is to use:
driver.get_tau_id = HiQIdGenerator()
This will allow you to create only one hiq.HiQLatency
object but will generate the same result as above.