Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[3.12] cProfile counts 0 primitive calls for builtins.exec in certain scenario #106152

Closed
jacobtylerwalls opened this issue Jun 27, 2023 · 6 comments
Closed

[3.12] cProfile counts 0 primitive calls for builtins.exec in certain scenario #106152

jacobtylerwalls opened this issue Jun 27, 2023 · 6 comments
Assignees
@gaogaotiantian
Labels
3.12 bugs and security fixes 3.13 bugs and security fixes type-bug An unexpected behavior, bug, or error

Comments

@jacobtylerwalls
Copy link
Contributor

jacobtylerwalls commented Jun 27, 2023 •
edited by bedevere-bot
Loading

Bug report

In 3.12, cProfile can count 0 primitive calls and miscalculate cumulative time in the following scenario.

For this layout:

script.py
project/
    typing.py

And the file contents:

script.py

import project.typing

project/typing.py

from typing import Protocol

class A(Protocol): ...

I observe this behavior difference with python3 -m cProfile script.py:

3.11.2

         697 function calls (693 primitive calls) in 0.001 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      2/1    0.000    0.000    0.001    0.001 {built-in method builtins.exec}
        1    0.000    0.000    0.001    0.001 script.py:1(<module>)

3.12.0b3

         635 function calls (630 primitive calls) in 0.001 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 script.py:1(<module>)
...
      1/0    0.000    0.000    0.000          {built-in method builtins.exec}

Notice the division by zero causing a missing percall stat for exec.

This means that in more substantial examples, the profiler will omit a significant portion of the relevant cumulative time. See this output for a 14.286 second script, I only have access to a cumtime for 0.800:

         45856453 function calls (31647888 primitive calls) in 14.286 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     4054    0.005    0.000    0.800    0.000 modutils.py:620(_spec_from_modpath)
    ...

Your environment

  • CPython versions tested on: Python 3.12.0b3
  • Operating system and architecture: MacOS 13.4.1

Linked PRs
@jacobtylerwalls jacobtylerwalls added the type-bug An unexpected behavior, bug, or error label Jun 27, 2023
@AlexWaygood AlexWaygood added 3.12 bugs and security fixes 3.13 bugs and security fixes labels Jun 27, 2023
@gaogaotiantian gaogaotiantian self-assigned this Jun 27, 2023
@gaogaotiantian
Copy link
Member

I'll take a look, it's probably related to either my changes to use PEP 669 for cProfile or PEP 669 itself.

@gaogaotiantian
Copy link
Member

For the second example, that's the only output from cProfile? Do you have a demo on that one? It seems like an easier example to follow up.

@jacobtylerwalls
Copy link
Contributor Author

jacobtylerwalls commented Jun 27, 2023 •
edited
Loading

For the second example, that's the only output from cProfile? Do you have a demo on that one? It seems like an easier example to follow up.

Sorry, it was truncated. I added an ellipsis.

Here is the full output.

To reproduce:

python3.12 -m pip install git+https://github.com/pylint-dev/pylint@8aa0d72ae1d5e3df55abdf5dea644cff1318fd15
python3.12 -m pip install git+https://github.com/pylint-dev/astroid@fef38f2dd474b0dacd1dda3f15abbf61eb0e9a71
echo "from pylint.lint import Run;Run(['astroid', '--disable=duplicate-code'])" > script.py
python3.12 -m cProfile script.py > out
3.12 result 
         44767175 function calls (30988647 primitive calls) in 14.130 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     7923    0.012    0.000    1.109    0.000 spec.py:427(find_spec)
     4034    0.006    0.000    1.108    0.000 modutils.py:620(_spec_from_modpath)
    12283    0.022    0.000    1.035    0.000 spec.py:371(_find_spec_with_path)
    12283    0.106    0.000    0.766    0.000 spec.py:129(find_module)
  7993860    0.637    0.000    0.685    0.000 {built-in method builtins.isinstance}
   276163    0.305    0.000    0.423    0.000 context.py:122(clone)
799932/396584    0.276    0.000    0.334    0.000 mixin.py:33(qname)
   290351    0.192    0.000    0.334    0.000 <frozen posixpath>:71(join)
   239314    0.060    0.000    0.327    0.000 <frozen genericpath>:27(isfile)
   251241    0.298    0.000    0.300    0.000 {built-in method posix.stat}
15626/13448    0.020    0.000    0.288    0.000 rebuilder.py:847(visit_call)
438865/124765    0.144    0.000    0.285    0.000 node_ng.py:308(frame)
    69080    0.062    0.000    0.265    0.000 rebuilder.py:1446(visit_name)
658578/234539    0.176    0.000    0.263    0.000 node_ng.py:291(statement)
136372/100670    0.031    0.000    0.240    0.000 context.py:183(copy_context)
      824    0.001    0.000    0.232    0.000 builder.py:477(_parse_string)
       36    0.000    0.000    0.226    0.006 __init__.py:1(<module>)
      824    0.001    0.000    0.226    0.000 _ast.py:25(parse)
      906    0.032    0.000    0.225    0.000 ast.py:34(parse)
9936/9333    0.014    0.000    0.217    0.000 rebuilder.py:730(visit_assign)
   374210    0.205    0.000    0.205    0.000 {built-in method _warnings.warn}
     1083    0.194    0.000    0.194    0.000 {built-in method builtins.compile}
    93/25    0.025    0.000    0.192    0.008 format.py:377(process_tokens)
   262973    0.191    0.000    0.191    0.000 node_ng.py:92(__init__)
 48623/48    0.030    0.000    0.188    0.004 scoped_nodes.py:2765(_inferred_bases)
   161/28    0.014    0.000    0.185    0.007 raw_building.py:467(object_build)
       15    0.000    0.000    0.176    0.012 raw_building.py:437(inspect_build)
    82819    0.077    0.000    0.171    0.000 constraint.py:84(get_constraints)
    14605    0.011    0.000    0.155    0.000 node_ng.py:626(as_string)
    63022    0.022    0.000    0.153    0.000 node_classes.py:481(__init__)
    26783    0.052    0.000    0.150    0.000 scoped_nodes.py:136(clean_duplicates_mro)
      101    0.012    0.000    0.147    0.001 unicode.py:519(process_module)
    14605    0.008    0.000    0.143    0.000 as_string.py:43(__call__)
19022/17207    0.023    0.000    0.134    0.000 rebuilder.py:1227(visit_attribute)

...

        1    0.000    0.000    0.000    0.000 dataclasses.py:879(_hash_set_none)
  11754/0    0.014    0.000    0.000          _base_nodes.py:124(do_import_module)
     11/0    0.000    0.000    0.000          manager.py:315(ast_from_module)
    551/0    0.000    0.000    0.000          manager.py:106(visit_transforms)
    674/0    0.002    0.000    0.000          rebuilder.py:179(visit_module)
 207467/0    0.146    0.000    0.000          transforms.py:77(_visit)
     13/0    0.000    0.000    0.000          node_classes.py:221(_infer_slice)
    558/0    0.000    0.000    0.000          transforms.py:145(visit)
  14563/0    0.013    0.000    0.000          scoped_nodes.py:416(import_module)
   1325/0    0.001    0.000    0.000          scoped_nodes.py:2182(local_attr_ancestors)
    458/0    0.001    0.000    0.000          builder.py:142(string_build)
     55/0    0.000    0.000    0.000          helpers.py:216(is_subtype)
     55/0    0.000    0.000    0.000          helpers.py:221(is_supertype)
      1/0    0.000    0.000    0.000          helpers.py:16(transform)
    883/0    0.001    0.000    0.000          builder.py:46(_can_assign_attr)
    111/0    0.000    0.000    0.000          helpers.py:203(_type_check)
 217647/0    0.080    0.000    0.000          rebuilder.py:537(visit)
    837/0    0.001    0.000    0.000          builder.py:67(__init__)
      1/0    0.000    0.000    0.000          brain_collections.py:112(easy_class_getitem_inference)
     75/0    0.000    0.000    0.000          ast_walker.py:37(_is_method_enabled)
     18/0    0.000    0.000    0.000          brain_dataclasses.py:50(<genexpr>)
     67/0    0.000    0.000    0.000          file_state.py:184(set_msg_status)
    381/0    0.004    0.000    0.000          {built-in method builtins.exec}
    412/0    0.001    0.000    0.000          <frozen importlib._bootstrap>:1255(_find_and_load)
    411/0    0.001    0.000    0.000          <frozen importlib._bootstrap>:1210(_find_and_load_unlocked)
      3/0    0.000    0.000    0.000          class_checker.py:860(visit_classdef)
   5598/0    0.010    0.000    0.000          class_checker.py:1572(visit_attribute)
   3494/0    0.006    0.000    0.000          variables.py:1604(visit_name)
   2551/0    0.002    0.000    0.000          class_checker.py:1719(visit_assign)
     52/0    0.000    0.000    0.000          typecheck.py:2286(visit_yieldfrom)
      6/0    0.000    0.000    0.000          typecheck.py:2304(visit_dictcomp)
      6/0    0.000    0.000    0.000          typecheck.py:2267(_check_mapping)
     14/0    0.000    0.000    0.000          class_checker.py:883(_check_consistent_mro)
      6/0    0.000    0.000    0.000          threading_checker.py:45(visit_with)
      3/0    0.000    0.000    0.000          refactoring_checker.py:630(process_tokens)
      1/0    0.000    0.000    0.000          exceptions.py:263(visit_classdef)
    194/0    0.001    0.000    0.000          recommendation_checker.py:176(visit_for)
     48/0    0.000    0.000    0.000          checker.py:553(_should_exempt_from_invalid_name)
    110/0    0.000    0.000    0.000          recommendation_checker.py:69(_is_builtin)
     50/0    0.000    0.000    0.000          implicit_booleaness_checker.py:183(visit_compare)
     99/0    0.000    0.000    0.000          checker.py:360(visit_classdef)
    182/0    0.000    0.000    0.000          refactoring_checker.py:1480(visit_boolop)
      1/0    0.000    0.000    0.000          exceptions.py:256(visit_instance)
     31/0    0.000    0.000    0.000          basic_checker.py:290(visit_ifexp)
   2041/0    0.005    0.000    0.000          refactoring_checker.py:1517(visit_assign)
    977/0    0.001    0.000    0.000          basic_error_checker.py:72(_has_abstract_methods)
     70/0    0.000    0.000    0.000          basic_error_checker.py:213(visit_classdef)
      1/0    0.000    0.000    0.000          basic_error_checker.py:49(_loop_exits_early)
   2856/0    0.002    0.000    0.000          scoped_nodes.py:2045(infer_call_result)
  10097/0    0.012    0.000    0.000          inference.py:279(infer_call)
   9615/0    0.014    0.000    0.000          inference.py:334(infer_import_from)
    172/0    0.000    0.000    0.000          inference.py:700(_invoke_binop_inference)
     93/0    0.000    0.000    0.000          inference.py:811(_get_binop_flow)
    216/0    0.001    0.000    0.000          inference.py:919(_infer_binary_operation)
    116/0    0.000    0.000    0.000          objects.py:279(__init__)
    374/0    0.000    0.000    0.000          protocols.py:270(_resolve_looppart)
      9/0    0.000    0.000    0.000          protocols.py:619(with_assigned_stmts)
    566/0    0.001    0.000    0.000          builder.py:150(_post_build)
     11/0    0.000    0.000    0.000          builder.py:75(module_build)
     49/0    0.000    0.000    0.000          builder.py:104(file_build)
   2468/0    0.004    0.000    0.000          inference_tip.py:39(inner)
      2/0    0.000    0.000    0.000          brain_builtin_inference.py:636(infer_bool)
     55/0    0.000    0.000    0.000          brain_builtin_inference.py:762(infer_isinstance)
     75/0    0.000    0.000    0.000          brain_builtin_inference.py:799(_class_or_tuple_to_container)
  17303/0    0.043    0.000    0.000          ast_walker.py:72(walk)
      1/0    0.000    0.000    0.000          utils.py:179(register_plugins)
 200850/0    0.160    0.000    0.000          file_state.py:56(_set_state_on_block_lines)
     20/0    0.000    0.000    0.000          pylinter.py:962(get_ast)
      3/0    0.000    0.000    0.000          utils.py:629(parse_format_method_string)
     34/0    0.001    0.000    0.000          utils.py:917(unimplemented_abstract_methods)
    121/0    0.002    0.000    0.000          utils.py:1134(class_is_abstract)
      2/0    0.000    0.000    0.000          utils.py:1979(is_hashable)
     23/0    0.000    0.000    0.000          typecheck.py:137(_)
      4/0    0.000    0.000    0.000          class_checker.py:2084(_check_bases_classes)
      2/0    0.000    0.000    0.000          variables.py:1983(visit_import)
     26/0    0.000    0.000    0.000          variables.py:2006(visit_importfrom)
    151/0    0.001    0.000    0.000          imports.py:530(visit_importfrom)
      5/0    0.000    0.000    0.000          imports.py:558(leave_module)
      6/0    0.000    0.000    0.000          exceptions.py:311(visit_raise)
      3/0    0.000    0.000    0.000          exceptions.py:360(_check_bad_exception_cause)
    143/0    0.000    0.000    0.000          stdlib.py:600(_check_lru_cache_decorators)
     27/0    0.000    0.000    0.000          refactoring_checker.py:1401(_apply_boolean_simplification_rules)
     25/0    0.000    0.000    0.000          refactoring_checker.py:1430(_simplify_boolean_operation)
    182/0    0.000    0.000    0.000          refactoring_checker.py:1452(_check_simplifiable_condition)
     50/0    0.000    0.000    0.000          checker.py:506(_raise_name_warning)
    460/0    0.000    0.000    0.000          manager.py:110(ast_from_file)
  14707/0    0.005    0.000    0.000          manager.py:184(ast_from_module_name)
     12/0    0.000    0.000    0.000          node_classes.py:1620(getitem)
    621/0    0.001    0.000    0.000          builder.py:171(_data_build)
      1/0    0.000    0.000    0.000          bases.py:400(getitem)
    141/0    0.000    0.000    0.000          scoped_nodes.py:806(_infer_decorator_callchain)
     10/0    0.000    0.000    0.000          bases.py:541(_infer_type_new_call)
      4/0    0.000    0.000    0.000          inference.py:663(_infer_old_style_string_formatting)
      9/0    0.000    0.000    0.000          protocols.py:581(_infer_context_manager)
     51/0    0.000    0.000    0.000          builder.py:228(delayed_assattr)
    545/0    0.002    0.000    0.000          rebuilder.py:863(visit_classdef)
     43/0    0.000    0.000    0.000          brain_namedtuple_enum.py:202(infer_named_tuple)
    118/0    0.000    0.000    0.000          brain_functools.py:75(_functools_partial_inference)
     20/0    0.000    0.000    0.000          brain_typing.py:152(infer_typing_attr)
      1/0    0.000    0.000    0.000          brain_builtin_inference.py:894(infer_dict_fromkeys)
    261/0    0.000    0.000    0.000          recommendation_checker.py:186(_check_consider_using_enumerate)
      2/0    0.000    0.000    0.000          typecheck.py:1857(visit_with)
     28/0    0.000    0.000    0.000          typecheck.py:425(_emit_no_member)
     70/0    0.000    0.000    0.000          utils.py:344(is_defined_before)
      6/0    0.000    0.000    0.000          imports.py:737(_check_imports_order)
    694/0    0.001    0.000    0.000          class_checker.py:1213(visit_functiondef)
     59/0    0.000    0.000    0.000          class_checker.py:1137(_check_attribute_defined_outside_init)
      6/0    0.000    0.000    0.000          exceptions.py:550(visit_tryexcept)
    305/0    0.001    0.000    0.000          implicit_booleaness_checker.py:198(_check_compare_to_str_or_zero)
      8/0    0.000    0.000    0.000          exceptions.py:423(_check_catching_non_exception)
   6832/0    0.002    0.000    0.000          class_checker.py:1771(_check_protected_attribute_access)
      6/0    0.000    0.000    0.000          class_checker.py:2189(_check_signature)
  10042/0    0.018    0.000    0.000          variables.py:1641(_undefined_and_used_before_checker)
   5930/0    0.020    0.000    0.000          variables.py:2487(_loopvar_name)
  24250/0    0.022    0.000    0.000          refactoring_checker.py:1942(_is_node_return_ended)
      3/0    0.000    0.000    0.000          basic_checker.py:832(_check_reversed)

@jacobtylerwalls
Copy link
Contributor Author

(PS - the name collision between typing.py and from typing import Protocol seemed essential.)

@bedevere-bot bedevere-bot mentioned this issue Jun 27, 2023
Merged
@gaogaotiantian
Copy link
Member

The reason for this is that I forgot the PY_THROW event when I was trying to restructure cProfile, which caused a missing start entry for any throw() of generators. cProfile does not check for "return matching start" and that's what caused the outer most function (exec in this case) missing counts.

In your second case, there's probably a generator that's doing this for multiple times which caused a lot of missing counts.

I've already submitted a PR and it's a simple fix. This should be merged back to 3.12 in the next release.

@jacobtylerwalls
Copy link
Contributor Author

Thanks for the brisk diagnosis and fix!

@bedevere-bot bedevere-bot mentioned this issue Jun 29, 2023
Merged
brandtbucher pushed a commit that referenced this issue Jun 29, 2023
@gaogaotiantian
GH-106152: Add PY_THROW event to cProfile (GH-106161)
cea9d4e
miss-islington pushed a commit to miss-islington/cpython that referenced this issue Jun 29, 2023
@gaogaotiantian @miss-islington
pythonGH-106152: Add PY_THROW event to cProfile (pythonGH-106161)
f80e76b 
(cherry picked from commit cea9d4e)

Co-authored-by: Tian Gao <[email protected]>
brandtbucher pushed a commit that referenced this issue Jun 29, 2023
@miss-islington @gaogaotiantian
[3.12] GH-106152: Add PY_THROW event to cProfile (GH-106256)
04a165f 
GH-106152: Add PY_THROW event to cProfile (GH-106161)
(cherry picked from commit cea9d4e)

Co-authored-by: Tian Gao <[email protected]>
@gaogaotiantian gaogaotiantian mentioned this issue Oct 8, 2023
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@gaogaotiantian gaogaotiantian

Labels
3.12 bugs and security fixes 3.13 bugs and security fixes type-bug An unexpected behavior, bug, or error
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@gaogaotiantian @jacobtylerwalls @brandtbucher @AlexWaygood