PyRFLX performance

[senier]

Of the 20 slowest test cases 12 are from the PyRFLX tests. We should analyse this performance issue and try to optimize it (especially to improve PyRFLX' viability for a fuzzer):

$ pytest --durations=20 tests/
...
46.52s call     tests/test_pyrflx.py::test_ipv4_parsing_ipv4
46.46s call     tests/test_pyrflx.py::test_ethernet_generating_udp_in_ipv4_in_ethernet
43.96s call     tests/test_integration.py::test_tls
24.97s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4_in_ethernet
23.28s call     tests/test_integration.py::test_feature_integeration
19.04s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2_vlan
18.85s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2_vlan
17.58s call     tests/test_pyrflx.py::test_ethernet_parse_binary
17.46s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2
17.11s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2
16.54s setup    tests/test_pyrflx.py::test_package_iterator
16.47s call     tests/test_pyrflx.py::test_ipv4_generating_ipv4
16.20s call     tests/test_parser.py::test_tls
15.15s call     tests/test_integration.py::test_icmp
14.78s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4
13.40s call     tests/test_integration.py::test_in_ethernet
13.02s call     tests/test_integration.py::test_in_ipv4
10.58s call     tests/test_pyrflx.py::test_incorrect_nested_message
10.26s call     tests/test_integration.py::test_ipv4
8.52s call     tests/test_parser.py::test_feature_integration

[treiher]

As far as I remember the invariants of ID had a significant impact on the performance of these unit tests. I would recommend to rerun the unit tests with disabled assertions and contracts (python -O -m pytest). There is certainly still something to be optimized. But I think the contracts shouldn't be considered during the performance analysis, as they will not be executed in production code.

[rssen]

I had a closer look on this and ran the tests myself for comparison.

slowest 20 with -O switch enabled

17.20s call     tests/test_integration.py::test_tls
14.38s setup    tests/test_pyrflx.py::test_package_iterator
14.13s call     tests/test_parser.py::test_tls
9.70s call     tests/test_integration.py::test_feature_integeration
8.73s call     tests/test_pyrflx.py::test_ipv4_parsing_ipv4
7.52s call     tests/test_pyrflx.py::test_ethernet_generating_udp_in_ipv4_in_ethernet
7.30s call     tests/test_parser.py::test_feature_integration
6.90s call     tests/test_integration.py::test_in_ethernet
6.15s call     tests/test_integration.py::test_icmp
6.02s call     tests/test_integration.py::test_in_ipv4
4.82s call     tests/test_integration.py::test_ipv4
3.82s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4_in_ethernet
3.16s call     tests/test_pyrflx.py::test_ipv4_generating_ipv4
2.99s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2_vlan
2.82s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4
2.62s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2_vlan
2.61s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2
2.46s call     tests/test_pyrflx.py::test_ethernet_parse_binary
2.46s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2
2.30s call     tests/test_parser.py::test_message_in_message

slowest 20 without -O switch

61.91s call     tests/test_pyrflx.py::test_ethernet_generating_udp_in_ipv4_in_ethernet
61.17s call     tests/test_pyrflx.py::test_ipv4_parsing_ipv4
39.45s call     tests/test_integration.py::test_tls
32.11s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4_in_ethernet
25.48s call     tests/test_integration.py::test_feature_integeration
25.17s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2_vlan
23.45s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2
23.01s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2_vlan
22.33s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2
21.42s call     tests/test_pyrflx.py::test_ethernet_parse_binary
20.81s call     tests/test_pyrflx.py::test_ipv4_generating_ipv4
19.47s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4
18.32s setup    tests/test_pyrflx.py::test_package_iterator
17.83s call     tests/test_parser.py::test_tls
16.27s call     tests/test_integration.py::test_in_ethernet
16.03s call     tests/test_integration.py::test_icmp
14.76s call     tests/test_integration.py::test_in_ipv4
13.25s call     tests/test_pyrflx.py::test_incorrect_nested_message
12.61s call     tests/test_integration.py::test_ipv4
9.27s call     tests/test_parser.py::test_feature_integration

I then profiled tests/test_pyrflx.py::test_ipv4_parsing_ipv4 using cProfile with -O switch enabled.
Results for typevalue:

>>> import pstats
>>> p = pstats.Stats("RecordFlux3.pstat")
>>> p.sort_stats('cumulative').print_stats('typevalue')
   Ordered by: cumulative time
   List reduced from 3985 to 80 due to restriction <'typevalue'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     4917    0.725    0.000   15.798    0.003 typevalue.py:828(__simplified)
       15    0.000    0.000   11.500    0.767 typevalue.py:719(get)
       15    0.000    0.000   11.500    0.767 typevalue.py:801(valid_fields)
       36    0.008    0.000   10.589    0.294 typevalue.py:762(accessible_fields)
      760    0.018    0.000    6.149    0.008 typevalue.py:540(_get_first_unchecked)
      601    0.001    0.000    5.676    0.009 typevalue.py:549(_has_first)
      2/1    0.000    0.000    4.345    4.345 typevalue.py:568(parse)
    21/16    0.000    0.000    4.259    0.266 typevalue.py:597(set_field_with_length)
    21/16    0.000    0.000    4.225    0.264 typevalue.py:646(set)
       15    0.006    0.000    3.886    0.259 typevalue.py:804(<listcomp>)
   298254    0.375    0.000    3.796    0.000 typevalue.py:861(set)
   276278    0.594    0.000    3.779    0.000 typevalue.py:870(last)
     4917    0.215    0.000    3.219    0.001 typevalue.py:837(<dictcomp>)
     4917    0.222    0.000    2.554    0.001 typevalue.py:835(<dictcomp>)
     4917    0.179    0.000    2.240    0.000 typevalue.py:836(<dictcomp>)
      636    0.010    0.000    2.086    0.003 typevalue.py:522(_get_length_unchecked)
      781    0.010    0.000    2.043    0.003 typevalue.py:514(_prev_field)
      707    0.009    0.000    1.899    0.003 typevalue.py:500(_next_field)
      576    0.000    0.000    1.801    0.003 typevalue.py:532(_has_length)
     4917    0.175    0.000    1.708    0.000 typevalue.py:830(<dictcomp>)
      240    0.004    0.000    1.305    0.005 typevalue.py:810(<listcomp>)
      240    0.004    0.000    1.301    0.005 typevalue.py:813(<listcomp>)
       44    0.001    0.000    1.189    0.027 typevalue.py:700(_preset_fields)
   496470    0.345    0.000    0.503    0.000 typevalue.py:138(size)
      159    0.000    0.000    0.475    0.003 typevalue.py:552(_get_first)
       29    0.001    0.000    0.329    0.011 typevalue.py:783(_is_valid_opaque_field)
       23    0.001    0.000    0.150    0.007 typevalue.py:465(__init__)
    25/23    0.000    0.000    0.141    0.006 typevalue.py:314(parse)
   ...

This is the complete call graph of tests/test_pyrflx.py::test_ipv4_parsing_ipv4 with -O enabled

see https://github.com/jrfonseca/gprof2dot#output

without -O enabled

RecordFlux3.zip

[treiher]

The call graph looks not very complete to me. Or why does _get_first_unchecked have no incoming edge?

[rssen]

Updated the first call graph.

[rssen]

I managed to improved the performance of all pyrflx tests (except for the package iterator test) by only updating the mapping in __simplified after a field has been set.

For example tests/test_pyrflx.py::test_ipv4_parsing_ipv4 when run with -O option takes now only 0.17 sec instead of 7.96 sec previously.

slowest 20 tests without perfomance fix and with -O option set

17.47s call     tests/test_integration.py::test_tls
14.09s setup    tests/test_pyrflx.py::test_package_iterator
13.91s call     tests/test_parser.py::test_tls
9.61s call     tests/test_integration.py::test_feature_integeration
7.96s call     tests/test_pyrflx.py::test_ipv4_parsing_ipv4
7.17s call     tests/test_parser.py::test_feature_integration
7.00s call     tests/test_pyrflx.py::test_ethernet_generating_udp_in_ipv4_in_ethernet
6.81s call     tests/test_integration.py::test_in_ethernet
6.33s call     tests/test_examples.py::test_icmp_socket
6.28s call     tests/test_integration.py::test_icmp
5.95s call     tests/test_integration.py::test_in_ipv4
4.76s call     tests/test_integration.py::test_ipv4
3.53s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4_in_ethernet
2.91s call     tests/test_pyrflx.py::test_ipv4_generating_ipv4
2.79s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2_vlan
2.62s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4
2.45s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2
2.43s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2_vlan
2.29s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2
2.28s call     tests/test_pyrflx.py::test_ethernet_parse_binary

slowest 20 with performance fix  and with -O option set

16.91s call     tests/test_integration.py::test_tls
13.99s setup    tests/test_pyrflx.py::test_package_iterator
13.86s call     tests/test_parser.py::test_tls
9.55s call     tests/test_integration.py::test_feature_integeration
7.18s call     tests/test_parser.py::test_feature_integration
6.77s call     tests/test_integration.py::test_in_ethernet
6.10s call     tests/test_integration.py::test_icmp
5.94s call     tests/test_integration.py::test_in_ipv4
5.65s call     tests/test_examples.py::test_icmp_socket
4.74s call     tests/test_integration.py::test_ipv4
2.23s call     tests/test_parser.py::test_message_in_message
1.73s call     tests/test_cli.py::test_main_generate_prefix
1.45s call     tests/test_integration.py::test_ethernet
1.27s call     tests/test_parser.py::test_ethernet_message
1.06s call     tests/test_parser.py::test_message_type_message
0.72s call     tests/test_cli.py::test_main_check_quiet
0.60s call     tests/test_integration.py::test_udp
0.45s call     tests/test_pyrflx.py::test_attributes
0.44s call     tests/test_model.py::test_message_copy
0.43s call     tests/test_integration.py::test_tlv

slowest 20 pyrflx tests with performance fix  and with -O option set

14.05s setup    tests/test_pyrflx.py::test_package_iterator
0.50s call     tests/test_pyrflx.py::test_attributes
0.27s call     tests/test_pyrflx.py::test_ethernet_generating_udp_in_ipv4_in_ethernet
0.17s call     tests/test_pyrflx.py::test_ipv4_parsing_ipv4
0.12s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4_in_ethernet
0.11s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2_vlan
0.11s call     tests/test_pyrflx.py::test_ipv4_generating_ipv4
0.10s call     tests/test_pyrflx.py::test_ethernet_parsing_ethernet_2
0.10s call     tests/test_pyrflx.py::test_ethernet_parse_binary
0.09s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2_vlan
0.09s call     tests/test_pyrflx.py::test_ipv4_parsing_udp_in_ipv4
0.09s call     tests/test_pyrflx.py::test_ethernet_generating_ethernet_2
0.08s call     tests/test_pyrflx.py::test_incorrect_nested_message
0.04s call     tests/test_pyrflx.py::test_ipv4_parsing_ipv4_option
0.03s call     tests/test_pyrflx.py::test_ipv4_generating_ipv4_option
0.02s call     tests/test_pyrflx.py::test_array_assign_incorrect_values
0.01s call     tests/test_pyrflx.py::test_ethernet_final
0.01s call     tests/test_pyrflx.py::test_tls_invalid_path
0.01s call     tests/test_pyrflx.py::test_icmp_echo_request
0.01s call     tests/test_pyrflx.py::test_icmp_parse_binary

[senier]

45x speedup? Very nice!

[senier]

@rssen Please file a PR against develop so we can all enjoy the speedup.