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.

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

line_profiler orders of magnitude slower when long list with large numbers present in function #82

Open
ta946 opened this issue May 25, 2021 · 7 comments
Labels
help wanted Extra attention is needed

Comments

@ta946
Copy link

ta946 commented May 25, 2021

quite a weird bug that I can't seem to wrap my head around...

this is the code to recreate:

from timeit import default_timer as time

@profile
def main():
    thisTimer = time()
    for i in range(500):
        9**0.5
    print('thisTimer', (round(1/(time()-thisTimer),1)if time()-thisTimer else 999), round(time()-thisTimer,6))
    return

    [4974505486916115, 57410050792361005, 636588158433384, 6929809317550536, 7474073920990998, 8029999935255876, 8684654854423644, 9422534008838399, 10200998795384454, 1094612106851126, 11815706683650723, 12874917812491984, 1411337098592753, 1522160984082089, 16174322390689582, 17163670468324634, 1763281431441779, 1655046814484683, 16032943383171198, 1607549667439851, 1658686572992698, 17326928744729014, 1771129104557067, 1656155241325528, 15307163320569828, 13976568981675638, 12601280585101307, 11306194271787162, 1007099447269723, 8862570423902685, 7549040644458472, 6138864379705228, 47605034215143974, 3517526262976634, 23226253086178076, 12555074597101793, 3343707123950935, 6956549722448301, 1984430050022371, 3340920097103674, 4448588272935035, 54803068535388206, 6621929260574927, 7813850766242649, 8855468199051086, 10117019181662806, 11469019870910665, 12662624402094826, 13569348543045157, 1435939966069551, 14994158976043695, 15398730126830824, 15674758853971124, 15830815646660716, 15871916274892632, 1580484432090226, 15626176822567848, 15343491173838044, 14976008035892784, 14558803467551866, 14106942375019315, 13625445484878975, 13126186749660735, 1261310966916273, 12067635602674173, 11471081343010283, 10815138529864817, 10122093264121975, 9410253012527426, 8714597247196821, 8059505735082939, 7446703412095792, 6787545414470975, 5982779387015944, 50733491568027716, 39771071675427265, 2605829516145036, 10317921125725434, 33239233545828597, 13954715555983512, 2067343287678443, 226857780445485, 22366079612272074, 22256899463941863, 23397298025337193, 24507475158348484, 25854166213395615, 27006483509558052, 2801701793080315, 29004824915433062, 3040331128585632, 31601083782597243, 3239900483762494, 32878343928937966, 3301062508964293, 3258349639539955, 3157973107410436, 30429105335247584, 2891645351121673, 2709744390712143, 24844705881119808, 22960089638220495, 14301135099465574, 15616657769289594, 16967853632184853, 1796485662858414, 171097067278709, 1640027003987056, 15782946014986993, 15271748879921265, 1496574186633395, 1496433523083896, 1524224867951774, 15789694969084456, 16596472836010517, 17816638610043736, 16676728986133, 15077842821909346, 13470242619972922, 11792672400256124, 10168596862251448, 8550319634143762, 6908198405689444, 5209366080755035, 3389640023380264, 1608705963308239, 7390808640454338, 16362541016178625, 3118151380103177, 45435905588057096, 5936992219462206, 7294597998193785, 8621048875046614, 9988376013220659, 11396612925180199, 12879512380113647, 14493130651845627, 1661460419203666, 16524682490243674, 13584273401149935, 11107678052186913, 892093559481259, 6856398856942832, 4878525525663713, 31945514168607133, 18330921300807972, 8193949038791402, 4803718623091413, 7478513961054659, 1408210602785482, 16686497984854668, 1609175582138164, 15006695121447592, 15806750343455633, 15754405396535049, 15849260641330147, 15998490073539188, 16030306700627875, 1596031395316561, 15839348342737367, 1585104607799991, 16129216852651837, 16700911290279578, 17393704525436306, 17970057169825736, 1818400734988103, 1778490091349346, 16386231421073717, 1386344099437224, 9831648351096874, 42128983868508385, 2446202803117046, 9410987842852535, 1604251286987079, 2177440154505109, 25975400526712406, 2889018500280315, 30709873512544732, 31785762125596534, 32293084850318905, 3241910009291536, 31978951637875866, 3086483566920498, 29509860732969173, 28342003623062283, 27402347900776192, 26533014642579246, 2599480057484311, 25864197825624842, 25966095982719025, 26387388677728666, 27188489561416645, 28448984184474682, 29613989563881432, 30541656913591055, 3117122338436593, 3197043412102113, 327931466405044, 33506500373402105, 34052244382918275, 3459450041126439, 3510068291266754, 35620398092854884, 3584466156317217, 9326629612549459, 9875652690053494, 10601972047851012, 11035047311033605, 9635632806879903, 8370270104614684, 7098291160563349, 5849214871082866, 4764743070949497, 40182141623277005, 3426541995867018, 29147771565924728, 24831018500829856, 2595028769222847, 5024065954434178, 2085827646415288, 4162571694444867, 47577957445907046, 586434652091975, 7525177040254749, 9678667324237537, 12117562663973979, 14321651022190406, 1495284644994704, 15233255234165284, 12340314880057775, 948312920499813, 6762603712981452, 4134002253235023, 15679724257088992, 1072008230588142, 3849511633515431, 6636109503665801, 9361986117137013, 12170505343227819, 1535909673232648, 1619031177784858, 12888618428905104, 9123248002164542, 55800154977089164, 24078105840077967, 6017813278751078, 3427377843714214, 5980758636161852, 8036073295171946, 10068981995431892, 107211684748052, 11254413799309344, 1190069874455969, 12750224078557346, 13493489463898936, 1381805509248526, 1409931831431762, 142458895825277, 14272067267538714, 14201813650839472, 14030145427251287, 13759556339564307, 13390903428092793, 12945881782286682, 12436851245991357, 11886075032335344, 11329181032678162, 10794708934174628, 10289145511324827, 9832458200902911, 9428794430427592, 9138928429012287, 8988963173842342, 8469976966885116, 7118406950797686, 5842452125108713, 4610105259965866, 33852393343447034, 21843306565224566, 9061198162882533, 5727466964146174, 2197516372459347, 29095176738332498, 18024236081892354, 10191402792420547, 6824082688420674, 5975924010790209, 5145448436834329, 31357166172420534, 14873254164946275, 10031612229226994, 10403875268390266, 16296292530744836, 18163353540164167, 19543271013816366, 19870942187158107, 18573479240338884, 17071205445720352, 10401909686218005, 20965024510485364, 19267692992977459, 36231390476706906, 5678046900047661, 8003239005546106, 10775692211735077, 12884571924951672]

if __name__ == '__main__':
    main();

when theres a long list with large numbers, the timing returns 0.01s but without the list its 0.0005s

this slow down doesnt happen if i comment out the list, or make the list a tuple, or combine the numbers into one large number since it could be due to the long line, or split the list into multiple lists or make all the numbers the same or any other changes.

It just seems to not like this specific case

@ta946
Copy link
Author

ta946 commented May 25, 2021

output of line_profiler

Timer unit: 1e-06 s

Total time: 0.0041987 s
File: test.py
Function: main at line 4

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     4       501       4198.7      8.4    100.0  @profile
     5                                           def main():
     6       501       2098.0      4.2     50.0      for i in range(500):
     7       500       2088.1      4.2     49.7          9**0.5
     8         1          8.5      8.5      0.2      [4974505486916115, 57410050792361005, 636588158433384, 6929809317550536, 7474073920990998, 8029999935255876, 8684654854423644, 9422534008838399, 10200998795384454, 1094612106851126, 11815706683650723, 12874917812491984, 1411337098592753, 1522160984082089, 16174322390689582, 17163670468324634, 1763281431441779, 1655046814484683, 16032943383171198, 1607549667439851, 1658686572992698, 17326928744729014, 1771129104557067, 1656155241325528, 15307163320569828, 13976568981675638, 12601280585101307, 11306194271787162, 1007099447269723, 8862570423902685, 7549040644458472, 6138864379705228, 47605034215143974, 3517526262976634, 23226253086178076, 12555074597101793, 3343707123950935, 6956549722448301, 1984430050022371, 3340920097103674, 4448588272935035, 54803068535388206, 6621929260574927, 7813850766242649, 8855468199051086, 10117019181662806, 11469019870910665, 12662624402094826, 13569348543045157, 1435939966069551, 14994158976043695, 15398730126830824, 15674758853971124, 15830815646660716, 15871916274892632, 1580484432090226, 15626176822567848, 15343491173838044, 14976008035892784, 14558803467551866, 14106942375019315, 13625445484878975, 13126186749660735, 1261310966916273, 12067635602674173, 11471081343010283, 10815138529864817, 10122093264121975, 9410253012527426, 8714597247196821, 8059505735082939, 7446703412095792, 6787545414470975, 5982779387015944, 50733491568027716, 39771071675427265, 2605829516145036, 10317921125725434, 33239233545828597, 13954715555983512, 2067343287678443, 226857780445485, 22366079612272074, 22256899463941863, 23397298025337193, 24507475158348484, 25854166213395615, 27006483509558052, 2801701793080315, 29004824915433062, 3040331128585632, 31601083782597243, 3239900483762494, 32878343928937966, 3301062508964293, 3258349639539955, 3157973107410436, 30429105335247584, 2891645351121673, 2709744390712143, 24844705881119808, 22960089638220495, 14301135099465574, 15616657769289594, 16967853632184853, 1796485662858414, 171097067278709, 1640027003987056, 15782946014986993, 15271748879921265, 1496574186633395, 1496433523083896, 1524224867951774, 15789694969084456, 16596472836010517, 17816638610043736, 16676728986133, 15077842821909346, 13470242619972922, 11792672400256124, 10168596862251448, 8550319634143762, 6908198405689444, 5209366080755035, 3389640023380264, 1608705963308239, 7390808640454338, 16362541016178625, 3118151380103177, 45435905588057096, 5936992219462206, 7294597998193785, 8621048875046614, 9988376013220659, 11396612925180199, 12879512380113647, 14493130651845627, 1661460419203666, 16524682490243674, 13584273401149935, 11107678052186913, 892093559481259, 6856398856942832, 4878525525663713, 31945514168607133, 18330921300807972, 8193949038791402, 4803718623091413, 7478513961054659, 1408210602785482, 16686497984854668, 1609175582138164, 15006695121447592, 15806750343455633, 15754405396535049, 15849260641330147, 15998490073539188, 16030306700627875, 1596031395316561, 15839348342737367, 1585104607799991, 16129216852651837, 16700911290279578, 17393704525436306, 17970057169825736, 1818400734988103, 1778490091349346, 16386231421073717, 1386344099437224, 9831648351096874, 42128983868508385, 2446202803117046, 9410987842852535, 1604251286987079, 2177440154505109, 25975400526712406, 2889018500280315, 30709873512544732, 31785762125596534, 32293084850318905, 3241910009291536, 31978951637875866, 3086483566920498, 29509860732969173, 28342003623062283, 27402347900776192, 26533014642579246, 2599480057484311, 25864197825624842, 25966095982719025, 26387388677728666, 27188489561416645, 28448984184474682, 29613989563881432, 30541656913591055, 3117122338436593, 3197043412102113, 327931466405044, 33506500373402105, 34052244382918275, 3459450041126439, 3510068291266754, 35620398092854884, 3584466156317217, 9326629612549459, 9875652690053494, 10601972047851012, 11035047311033605, 9635632806879903, 8370270104614684, 7098291160563349, 5849214871082866, 4764743070949497, 40182141623277005, 3426541995867018, 29147771565924728, 24831018500829856, 2595028769222847, 5024065954434178, 2085827646415288, 4162571694444867, 47577957445907046, 586434652091975, 7525177040254749, 9678667324237537, 12117562663973979, 14321651022190406, 1495284644994704, 15233255234165284, 12340314880057775, 948312920499813, 6762603712981452, 4134002253235023, 15679724257088992, 1072008230588142, 3849511633515431, 6636109503665801, 9361986117137013, 12170505343227819, 1535909673232648, 1619031177784858, 12888618428905104, 9123248002164542, 55800154977089164, 24078105840077967, 6017813278751078, 3427377843714214, 5980758636161852, 8036073295171946, 10068981995431892, 107211684748052, 11254413799309344, 1190069874455969, 12750224078557346, 13493489463898936, 1381805509248526, 1409931831431762, 142458895825277, 14272067267538714, 14201813650839472, 14030145427251287, 13759556339564307, 13390903428092793, 12945881782286682, 12436851245991357, 11886075032335344, 11329181032678162, 10794708934174628, 10289145511324827, 9832458200902911, 9428794430427592, 9138928429012287, 8988963173842342, 8469976966885116, 7118406950797686, 5842452125108713, 4610105259965866, 33852393343447034, 21843306565224566, 9061198162882533, 5727466964146174, 2197516372459347, 29095176738332498, 18024236081892354, 10191402792420547, 6824082688420674, 5975924010790209, 5145448436834329, 31357166172420534, 14873254164946275, 10031612229226994, 10403875268390266, 16296292530744836, 18163353540164167, 19543271013816366, 19870942187158107, 18573479240338884, 17071205445720352, 10401909686218005, 20965024510485364, 19267692992977459, 36231390476706906, 5678046900047661, 8003239005546106, 10775692211735077, 12884571924951672]
     9         1          4.1      4.1      0.1      return

without line:

Timer unit: 1e-06 s

Total time: 0.0002429 s
File: test.py
Function: main at line 4

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     4       501        242.9      0.5    100.0  @profile
     5                                           def main():
     6       501        124.3      0.2     51.2      for i in range(500):
     7       500        118.3      0.2     48.7          9**0.5
     8                                               # [4974505486916115, 57410050792361005, 636588158433384, 6929809317550536, 7474073920990998, 8029999935255876, 8684654854423644, 9422534008838399, 10200998795384454, 1094612106851126, 11815706683650723, 12874917812491984, 1411337098592753, 1522160984082089, 16174322390689582, 17163670468324634, 1763281431441779, 1655046814484683, 16032943383171198, 1607549667439851, 1658686572992698, 17326928744729014, 1771129104557067, 1656155241325528, 15307163320569828, 13976568981675638, 12601280585101307, 11306194271787162, 1007099447269723, 8862570423902685, 7549040644458472, 6138864379705228, 47605034215143974, 3517526262976634, 23226253086178076, 12555074597101793, 3343707123950935, 6956549722448301, 1984430050022371, 3340920097103674, 4448588272935035, 54803068535388206, 6621929260574927, 7813850766242649, 8855468199051086, 10117019181662806, 11469019870910665, 12662624402094826, 13569348543045157, 1435939966069551, 14994158976043695, 15398730126830824, 15674758853971124, 15830815646660716, 15871916274892632, 1580484432090226, 15626176822567848, 15343491173838044, 14976008035892784, 14558803467551866, 14106942375019315, 13625445484878975, 13126186749660735, 1261310966916273, 12067635602674173, 11471081343010283, 10815138529864817, 10122093264121975, 9410253012527426, 8714597247196821, 8059505735082939, 7446703412095792, 6787545414470975, 5982779387015944, 50733491568027716, 39771071675427265, 2605829516145036, 10317921125725434, 33239233545828597, 13954715555983512, 2067343287678443, 226857780445485, 22366079612272074, 22256899463941863, 23397298025337193, 24507475158348484, 25854166213395615, 27006483509558052, 2801701793080315, 29004824915433062, 3040331128585632, 31601083782597243, 3239900483762494, 32878343928937966, 3301062508964293, 3258349639539955, 3157973107410436, 30429105335247584, 2891645351121673, 2709744390712143, 24844705881119808, 22960089638220495, 14301135099465574, 15616657769289594, 16967853632184853, 1796485662858414, 171097067278709, 1640027003987056, 15782946014986993, 15271748879921265, 1496574186633395, 1496433523083896, 1524224867951774, 15789694969084456, 16596472836010517, 17816638610043736, 16676728986133, 15077842821909346, 13470242619972922, 11792672400256124, 10168596862251448, 8550319634143762, 6908198405689444, 5209366080755035, 3389640023380264, 1608705963308239, 7390808640454338, 16362541016178625, 3118151380103177, 45435905588057096, 5936992219462206, 7294597998193785, 8621048875046614, 9988376013220659, 11396612925180199, 12879512380113647, 14493130651845627, 1661460419203666, 16524682490243674, 13584273401149935, 11107678052186913, 892093559481259, 6856398856942832, 4878525525663713, 31945514168607133, 18330921300807972, 8193949038791402, 4803718623091413, 7478513961054659, 1408210602785482, 16686497984854668, 1609175582138164, 15006695121447592, 15806750343455633, 15754405396535049, 15849260641330147, 15998490073539188, 16030306700627875, 1596031395316561, 15839348342737367, 1585104607799991, 16129216852651837, 16700911290279578, 17393704525436306, 17970057169825736, 1818400734988103, 1778490091349346, 16386231421073717, 1386344099437224, 9831648351096874, 42128983868508385, 2446202803117046, 9410987842852535, 1604251286987079, 2177440154505109, 25975400526712406, 2889018500280315, 30709873512544732, 31785762125596534, 32293084850318905, 3241910009291536, 31978951637875866, 3086483566920498, 29509860732969173, 28342003623062283, 27402347900776192, 26533014642579246, 2599480057484311, 25864197825624842, 25966095982719025, 26387388677728666, 27188489561416645, 28448984184474682, 29613989563881432, 30541656913591055, 3117122338436593, 3197043412102113, 327931466405044, 33506500373402105, 34052244382918275, 3459450041126439, 3510068291266754, 35620398092854884, 3584466156317217, 9326629612549459, 9875652690053494, 10601972047851012, 11035047311033605, 9635632806879903, 8370270104614684, 7098291160563349, 5849214871082866, 4764743070949497, 40182141623277005, 3426541995867018, 29147771565924728, 24831018500829856, 2595028769222847, 5024065954434178, 2085827646415288, 4162571694444867, 47577957445907046, 586434652091975, 7525177040254749, 9678667324237537, 12117562663973979, 14321651022190406, 1495284644994704, 15233255234165284, 12340314880057775, 948312920499813, 6762603712981452, 4134002253235023, 15679724257088992, 1072008230588142, 3849511633515431, 6636109503665801, 9361986117137013, 12170505343227819, 1535909673232648, 1619031177784858, 12888618428905104, 9123248002164542, 55800154977089164, 24078105840077967, 6017813278751078, 3427377843714214, 5980758636161852, 8036073295171946, 10068981995431892, 107211684748052, 11254413799309344, 1190069874455969, 12750224078557346, 13493489463898936, 1381805509248526, 1409931831431762, 142458895825277, 14272067267538714, 14201813650839472, 14030145427251287, 13759556339564307, 13390903428092793, 12945881782286682, 12436851245991357, 11886075032335344, 11329181032678162, 10794708934174628, 10289145511324827, 9832458200902911, 9428794430427592, 9138928429012287, 8988963173842342, 8469976966885116, 7118406950797686, 5842452125108713, 4610105259965866, 33852393343447034, 21843306565224566, 9061198162882533, 5727466964146174, 2197516372459347, 29095176738332498, 18024236081892354, 10191402792420547, 6824082688420674, 5975924010790209, 5145448436834329, 31357166172420534, 14873254164946275, 10031612229226994, 10403875268390266, 16296292530744836, 18163353540164167, 19543271013816366, 19870942187158107, 18573479240338884, 17071205445720352, 10401909686218005, 20965024510485364, 19267692992977459, 36231390476706906, 5678046900047661, 8003239005546106, 10775692211735077, 12884571924951672]
     9         1          0.3      0.3      0.1      return


@Erotemic
Copy link
Member

Interesting behavior.

  • What is the Python version?

  • Did you try timing this without line profiler to see if it is fast when running without it? (It could be that Python itself is slow when you include this long list in the bytecode).

@ta946
Copy link
Author

ta946 commented May 25, 2021

python 3.7.7
running without line_profiler: 3.9e-05s
running with line_profiler but without @Profile shows no slow down

moving the line outside the function being profiled also shows no slow down. trust me i tried every combination i could think of trying to isolate the issue

@Erotemic
Copy link
Member

Erotemic commented Sep 5, 2021

This is very strange. I've reproduced the issue. The bytecode also shows no noticable difference:

  6           0 LOAD_GLOBAL              0 (time)        |  15           0 LOAD_GLOBAL              0 (time)
              2 CALL_FUNCTION            0                               2 CALL_FUNCTION            0
              4 STORE_FAST               0 (thisTimer)                   4 STORE_FAST               0 (thisTimer)

  7           6 LOAD_GLOBAL              1 (range)          16           6 LOAD_GLOBAL              1 (range)
              8 LOAD_CONST               1 (500)                         8 LOAD_CONST               1 (500)
             10 CALL_FUNCTION            1                              10 CALL_FUNCTION            1
             12 GET_ITER                                                12 GET_ITER
        >>   14 FOR_ITER                 4 (to 20)                 >>   14 FOR_ITER                 4 (to 20)
             16 STORE_FAST               1 (i)                          16 STORE_FAST               1 (i)

  8          18 JUMP_ABSOLUTE           14                  17          18 JUMP_ABSOLUTE           14

  9     >>   20 LOAD_GLOBAL              2 (print)          18     >>   20 LOAD_GLOBAL              2 (print)
             22 LOAD_CONST               2 ('thisTimer')                22 LOAD_CONST               2 ('thisTimer')
             24 LOAD_GLOBAL              0 (time)                       24 LOAD_GLOBAL              0 (time)
             26 CALL_FUNCTION            0                              26 CALL_FUNCTION            0
             28 LOAD_FAST                0 (thisTimer)                  28 LOAD_FAST                0 (thisTimer)
             30 BINARY_SUBTRACT                                         30 BINARY_SUBTRACT
             32 POP_JUMP_IF_FALSE       54                              32 POP_JUMP_IF_FALSE       54
             34 LOAD_GLOBAL              3 (round)                      34 LOAD_GLOBAL              3 (round)
             36 LOAD_CONST               3 (1)                          36 LOAD_CONST               3 (1)
             38 LOAD_GLOBAL              0 (time)                       38 LOAD_GLOBAL              0 (time)
             40 CALL_FUNCTION            0                              40 CALL_FUNCTION            0
             42 LOAD_FAST                0 (thisTimer)                  42 LOAD_FAST                0 (thisTimer)
             44 BINARY_SUBTRACT                                         44 BINARY_SUBTRACT
             46 BINARY_TRUE_DIVIDE                                      46 BINARY_TRUE_DIVIDE
             48 LOAD_CONST               3 (1)                          48 LOAD_CONST               3 (1)
             50 CALL_FUNCTION            2                              50 CALL_FUNCTION            2
             52 JUMP_FORWARD             2 (to 56)                      52 JUMP_FORWARD             2 (to 56)
        >>   54 LOAD_CONST               4 (999)                   >>   54 LOAD_CONST               4 (999)
        >>   56 LOAD_GLOBAL              3 (round)                 >>   56 LOAD_GLOBAL              3 (round)
             58 LOAD_GLOBAL              0 (time)                       58 LOAD_GLOBAL              0 (time)
             60 CALL_FUNCTION            0                              60 CALL_FUNCTION            0
             62 LOAD_FAST                0 (thisTimer)                  62 LOAD_FAST                0 (thisTimer)
             64 BINARY_SUBTRACT                                         64 BINARY_SUBTRACT
             66 LOAD_CONST               5 (6)                          66 LOAD_CONST               5 (6)
             68 CALL_FUNCTION            2                              68 CALL_FUNCTION            2
             70 CALL_FUNCTION            3                              70 CALL_FUNCTION            3
             72 POP_TOP                                                 72 POP_TOP

 10          74 LOAD_CONST               0 (None)           19          74 LOAD_CONST               0 (None)
             76 RETURN_VALUE                                            76 RETURN_VALUE

I'm not sure if this is a line-profiler bug, but it is certainly peculiar.

@ogencoglu
Copy link

Any updates?

@Erotemic
Copy link
Member

Erotemic commented Oct 5, 2024

No updates, but we do expect profiling to add some amount of overhead to the code. This does seem to be on the high side.

My guess is that this will have to do with how Python is representing the function and perhaps reference counting. The LOAD_CONST in the byte code likely correspond to it accessing the value of this large list. Perhaps there is some sort of memory transport overhead (e.g. an L1 / L2 cache miss or memory paging) in referencing counting everything in that list, whereas for a tuple maybe the reference count only happens on the top level because the tuple is immutable?

I wonder if it happens if you make this a dictionary. My guess is that it will also have the slow behavior. I'm going to try some tests.

@Erotemic
Copy link
Member

Erotemic commented Oct 5, 2024

I've written a script to help test this in a more principled way.

Expand details to see testing script:

"""
Requirements:
    pip install ubelt kwplot line_profiler rich pandas
"""

import ubelt as ub


def main():
    import random
    rng = random.Random(8675309)

    test_dpath = ub.Path.appdir('line_profiler/tests/test_issue_82').ensuredir()
    results = []

    template = ub.codeblock(
        '''
        #from timeit import default_timer as time
        from line_profiler import profile

        @profile
        def main():
            #thisTimer = time()
            for i in range(500):
                9**0.5
            #print('thisTimer', (round(1/(time()-thisTimer),1)if time()-thisTimer else 999), round(time()-thisTimer,6))

            {const_line}
            return

        if __name__ == '__main__':
            main()
        ''')

    for size in [10, 300, 500, 1000, 1_500, 5_000, 10_000]:
        list_numbers = [rng.randint(0, 12884571924951672) for _ in range(size)]
        dict_numbers = {k: k for k in list_numbers}
        list_small_numbers = [rng.randint(0, 10) for _ in range(size)]
        list_same_number = [12884571924951672] * size

        variants = {
            'nothing': '',
            'list_numbers': repr(list_numbers),
            'comment_list_numbers': '# ' + repr(list_numbers),
            'dict_numbers': repr(dict_numbers),
            'list_small_numbers': repr(list_small_numbers),
            'list_same_number': repr(list_same_number),
            'tuple_numbers': repr(tuple(list_numbers)),
        }

        for name, const_line in variants.items():
            script_fpath = test_dpath / f'{name}.py'
            text = template.format(const_line=const_line)
            script_fpath.write_text(text)

            for LINE_PROFILE in [0, 1]:
                with ub.Timer() as t:
                    ub.cmd(f'LINE_PROFILE={LINE_PROFILE} python {script_fpath}', verbose=3, shell=True)
                row = {
                    'name': name,
                    'size': size,
                    'script_fpath': script_fpath,
                    'LINE_PROFILE': LINE_PROFILE,
                    'duration': t.elapsed,
                }
                results.append(row)
    import pandas as pd
    import rich
    table = pd.DataFrame(results)
    piv = table.pivot(index=['name', 'size'], columns=['LINE_PROFILE'], values=['duration'])
    rich.print(table.to_string())
    rich.print(piv.to_string())

    import kwplot
    sns = kwplot.autosns()
    ax = sns.lineplot(data=table, x='size', y='duration', hue='LINE_PROFILE', style='name')
    ax.set_yscale('log')
    kwplot.show_if_requested()


if __name__ == '__main__':
    """
    CommandLine:
        python ~/code/line_profiler/dev/devcheck/generate_examples_issue_82.py
    """
    main()

This will make a copy of the above script, but put in different variants of the hard-coded constant and time them with and without line profiler active.

Interestingly I'm not seeing a difference on the current machine I'm using with line profiler 4.1.4, but on my main machine I do see a difference with 4.2.0.

Graph from main machine:

image

Graph from current machine:

image

EDIT: I've changed testing script to test more sizes and use a log scale and found a clear pattern:

image

@Erotemic Erotemic added the help wanted Extra attention is needed label Oct 5, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
help wanted Extra attention is needed
Projects
None yet
Development

No branches or pull requests

3 participants