if/elif `Hits` counts only count True cases or only count False cases

[zig1000]

I am getting what appear to be contradictory hit counts on a simple if/elif chain:

Timer unit: 1e-07 s

Total time: 0.0001399 s
File: ...
Function: check_wall_collisions_lazy at line 1506

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
  1506                                               def check_wall_collisions_lazy(self, molecule, direction):
  1507                                                   """Raise an exception if the given molecule collides with the specified wall."""
  1508        13         74.0      5.7      5.3          if direction == RIGHT:
  1509        13        536.0     41.2     38.3              if all(p.col < self.NUM_COLS for p in molecule.atom_map):
  1510        13         52.0      4.0      3.7                  return
  1511         8         33.0      4.1      2.4          elif direction == UP:
  1512         5        178.0     35.6     12.7              if all(p.row >= 0 for p in molecule.atom_map):
  1513         5         21.0      4.2      1.5                  return
  1514         6         25.0      4.2      1.8          elif direction == DOWN:
  1515         6        353.0     58.8     25.2              if all(p.row < self.NUM_ROWS for p in molecule.atom_map):
  1516         6         24.0      4.0      1.7                  return
  1517         2          8.0      4.0      0.6          elif direction == LEFT:
  1518         2         89.0     44.5      6.4              if all(p.col >= 0 for p in molecule.atom_map):
  1519         2          6.0      3.0      0.4                  return
  1520
  1521                                                   raise ReactionError("A molecule has collided with a wall")

Note how the first and third blocks have the same hit counts on their condition as their inner contents, despite all blocks clearly being hit. This function is the only one being profiled, so I don't believe the known bug of one profiler function calling another is related. Also worth noting I'm calling the profiler programmatically. The actual timings look more reasonable.

Are hit counts being fuzzy a known issue?

This is on v4.0.3

[Erotemic]

That is odd. I don't believe hit counts are fuzzy. Do you have a minimal example that produces this? What version of Python and line_profiler are you running?

[zig1000]

Sorry for the late reply, here's some reproduce steps. Definitely not minimal sorry, but I did find that it reproduces even when calling the line profiler non-programmatically:

1. pip install line-profiler v4.03 in py 3.11.0 also in 3.11.3. Probably reproduces in other py versions too.
2. clone https://github.com/spacechem-community-developers/SChem
3. Edit schem/components.py to find and add an @profile in front of check_wall_collisions_lazy
4. In the base directory of the cloned repo, create a blah.py with the following contents:

import schem
from tests import test_data

soln_str = next((s for s in test_data.valid_solutions
                 if schem.Solution.parse_metadata(s) == ("An Introduction to Bonding", "Zig", (74, 1, 40), "Cycles")),
                None)

if __name__ == '__main__':
    schem.Solution(soln_str).run()

5. Run kernprof -lv blah.py

Results will be as in the description.

[zig1000]

Having looked at a much longer if/elif chain (change the profile function to exec_waldo_cmd in the same file), I am seeing the pattern: The hit counts on if/elif lines is not the total number of times the condition was tested - instead, sometimes it's the number of times the condition evaluated to true, and sometimes it's the number of times the condition evaluated to false.

In the wall collisions example, the UP case is showing the eval-to-false count and all others are showing the eval-to-true count. The function is hit a total of 25 times.

[zig1000]

Here's the minimal example:

@profile
def silly_example():
    for i in range(7):
        if i % 2 == 0:
            print("even")
        elif i == 1:
            print("one")
        else:
            print("three or five")

if __name__ == '__main__':
    silly_example()

which produces:

Function: silly_example at line 2

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     2                                           @profile
     3                                           def silly_example():
     4         7         10.4      1.5      0.5      for i in range(7):
     5         4          3.5      0.9      0.2          if i % 2 == 0:                  # `True` count
     6         4       1248.3    312.1     64.0              print("even")
     7         2          1.1      0.6      0.1          elif i == 1:                    # `False` count
     8         1        470.9    470.9     24.1              print("one")
     9                                                   else:
    10         2        217.7    108.9     11.2              print("three or five")

[Theelx]

This is an extremely interesting issue. I'm going to investigate and try to fix this ASAP.

[Theelx]

Update: The side trace callback is collecting all the hits properly, it seems the issue is with displaying the stats inside get_stats() inside _line_profiler.pyx.