PERF/TST: Figure out what's going on with vb_suite test result instability (`frame_reindex_*` in particular)

[stephenwlin]

Example:

frame_reindex_axis1                  3.1934       2.0423       1.5636
frame_reindex_axis0                  1.4083       0.4687       3.0049

Target [b42175f] : dummy commit
Base   [da54321] : SCR: format tweaks to test_perf

with the following:

stephen@trantor:~/Projects/pandas$ git diff da54321 b42175f
diff --git a/TODO.rst b/TODO.rst
index fc87174..97aa56f 100644
--- a/TODO.rst
+++ b/TODO.rst
@@ -1,6 +1,6 @@
 DOCS 0.7.0
 ----------
-- ??? no sort in groupby
+- ???? no sort in groupby
 - DONE concat with dict
 - Gotchas re: integer indexing

These random outliers are making it hard to figure out what's really happening (the optimization I wanted to test seems to improve things by 25%-40% in a C testbed, but I can't get clean results.)

These tests aren't doing anything fancy either, so if they're affected, it's possible the entire suite is affected as well (just less dramatically...)

Possibly some combination of #3129, #3146 (cache and alignment) are related, or maybe some other source of non-determinism in Python and numpy. I can't reproduce this instability in C by trying to proxy it either by randomly adjusting byte alignment, but I haven't tried screwing around with memory paging yet.

[stephenwlin]

(I suspect the problem is due to positive but non-deterministic performance optimizations, which means that, if we can't resolve the source of the non-determinism, then we have to choose between less consistent but better average performance versus more consistent but worse average performance, which is not a nice choice.)

[stephenwlin]

It doesn't seem like memmove() is the culprit of frame_reindex_axis0 instability:

-- frame_reindex_axis0 --
mean change with dummy == -0.0048 (i.e. -0.48%)
stddev change with dummy == 0.3068 (i.e. 35.91%)
hypothesis: mean change with dummy != 0.0 => p == 0.8760 (insignificant)
mean change with memmove == 0.0148 (i.e. 1.50%)
stddev change with memmove == 0.3442 (i.e. 41.09%)
hypothesis: mean change with memmove != 0.0 => p == 0.6673 (insignificant)
hypothesis: variance of change greater with dummy => p == 0.8743 (insignificant)
hypothesis: variance of change greater with memmove => p == 0.1257 (insignificant)
hypothesis: variance of change differs => p == 0.2515 (insignificant)

The changes quoted (before the percentage values) are natural logs of the ratios (target/base).

This is based on three commits: the base commit is current master but with memmove() disabled, dummy is a commit based on the base commit with a null change, and memmove is a commit based on base with memmove() re-enabled. The results are based on 100 vbench runs each of dummy vs base and memmove vs base. The variance is nominally greater in the memmove case but it doesn't seem like the results are significant (p < 0.05).

It's possible my p-values are off, but in any case just grepping the results makes clear that the large variance was present without memmove(). A lot of other results are somewhat curious, too...still trying to analyze it to make sure I haven't done anything wrong.

added -n to control number of vb runs to average over for each vb
added -N to collect results from repeated runs on HEAD, that should make it very
easy to get min, max, variance, etc'. even confidence intervals.

λ time ./test_perf.sh -H -N 3 -r axis0 -d o.pickle
This script compares the performance of two commits.
Make sure the python 'vbench' library is installed.

Setting the BUILD_CACHE_DIR env var to a temp directory will
potentially speed up subsequent runs.

*** LOG_FILE = /home/user1/src/pandas/vb_suite.log

profile_head
Running 2 benchmarks
Running 2 benchmarks
Running 2 benchmarks
*** 
------------------------------------------------------------------------
Test name                       |     #0     |     #1     |     #2     |
------------------------------------------------------------------------
frame_reindex_axis0             |     0.9001 |     0.8989 |     0.8986 |
stats_rank2d_axis0_average      |    40.2542 |    40.3576 |    40.2745 |
------------------------------------------------------------------------
Test name                       |     #0     |     #1     |     #2     |
------------------------------------------------------------------------

Ratio < 1.0 means the target commit is faster then the baseline.
Seed used: 1234

Target [3844347] : BLD: test_perf, add -N, run HEAD vbenchmarks multiple times seperately

*** Results were also written to the logfile at '/home/user1/src/pandas/vb_suite.log'
*** The results DataFrame was written to '/home/user1/src/pandas/o.pickle'


real    0m18.495s
user    0m17.718s
sys 0m0.762s

Pushed some more bells and whistles to test_perf, vb_suite let's the timeit module choose
it's own iteration count, which led to excessive runtimes without any boost to stability of results
afaict, now controllable via the -c/--ncalls cmd arg.

I ran a few iterations, still variable (though much quicker about it), one
thing I seem to notice is that the variation is strongly bimodal, even though
my box was quiet for the duration. Also, when there's a spike,
it runs through the entire suite, see columns #1 and #3.

                                                 #0          #1          #2          #3          #4
name                                                                                               
setattr_dataframe_index                    0.004625    0.003004    0.003195    0.004816    0.004578
getattr_dataframe_index                    0.000191    0.000191    0.000191    0.000191    0.000191
frame_mult_no_ne                          10.584211   10.447598   10.479403   11.007833   12.671614
frame_add                                 10.768604   10.713387   10.706806   10.860205   11.874008
frame_multi_and_no_ne                    106.887960  125.117826   95.654011   92.890835   96.286201
frame_add_no_ne                           10.350227   11.106586   10.406637   10.443211   10.560036
frame_multi_and_st                        45.163012   60.193014   45.246792   45.523214   46.834993
frame_mult_st                             10.841370   11.248827   10.709620   10.581207   11.228418
frame_multi_and                           43.519592   43.063021   35.759592   34.731817   36.842394
frame_mult                                10.872030   10.694170   10.713577   10.757208   11.470413
frame_add_st                              11.837816   11.473227   11.109018   11.459017   10.744190
series_constructor_ndarray                 0.013399    0.020409    0.013638    0.020790    0.013399
frame_constructor_ndarray                  0.040627    0.063610    0.043201    0.063801    0.043392
ctor_index_array_string                    0.014162    0.020981    0.014019    0.020981    0.014162
series_ctor_from_dict                      2.901793    4.373789    2.982616    4.417038    2.894592
frame_get_numeric_data                     0.058603    0.089598    0.059795    0.091028    0.059414
frame_ctor_nested_dict_int64              99.905586  147.639990   99.647570  144.639587  102.165985
frame_ctor_nested_dict                    80.397224  116.105175   79.887819  114.512205   82.165766
frame_ctor_list_of_dict                  104.632187  136.345196  103.941393  134.804010  105.473423
frame_boolean_row_select                   0.201607    0.296593    0.197792    0.312614    0.199986
frame_reindex_both_axes                    0.331402    0.499201    0.333214    0.499964    0.332403
frame_fancy_lookup                         1.435184    2.169800    1.453590    2.197599    1.404572
frame_iteritems_cached                     0.054598    0.083017    0.055981    0.081015    0.053406
frame_reindex_both_axes_ix                 0.406599    0.612402    0.409603    0.611019    0.409174
frame_insert_500_columns                  90.004826  132.124567   89.684772  131.825781   90.292788
frame_get_dtype_counts                     0.096035    0.144386    0.103378    0.145435    0.095987
frame_wide_repr                            0.554991    0.826406    0.556040    0.818205    0.549984
frame_iteritems                            2.042198    3.060579    2.065802    3.067398    2.058601
frame_fancy_lookup_all                    29.863596   30.314827   24.519205   32.511568   23.088789
frame_fillna_inplace                      15.973997   19.704390   15.753412   19.800377   15.702391
series_string_vector_slice               190.852976  275.263023  188.290787  273.380995  190.084171
frame_reindex_upcast                      22.756624   28.754187   20.848370   27.637005   21.184397
frame_to_string_floats                    44.160223   64.106607   43.102169   63.887978   42.306566
frame_reindex_axis0                        1.006842    0.920630    0.856400    0.931978    0.858164
frame_reindex_axis1                        2.419615    3.101826    2.277994    3.038025    2.289772
groupby_multi_different_functions         15.848398   22.987604   15.746832   22.593784   15.834999
groupby_frame_apply_overhead               9.788418   14.041424    9.688568   14.140987    9.358597
groupby_frame_median                       9.151220   12.225819    8.844614   12.213230    8.840609
series_value_counts_strings                4.848003    7.175398    4.818583    7.148600    4.795408
groupby_apply_dict_return                 48.514414   73.194981   50.197601   73.086405   48.549414
groupby_frame_cython_many_columns          4.768229    5.860615    4.372168    5.847406    4.351425
groupby_indices                           10.500813   14.535189   11.385632   14.624834   10.096216
groupby_first_float32                      5.170012    6.640196    4.579020    6.672382    4.540825
groupby_last_float32                       5.550194    7.085371    4.863214    7.158184    4.772377
groupby_multi_cython                      20.029211   27.652216   19.573402   28.120232   19.629812
series_value_counts_int64                  2.928400    4.360199    2.777624    4.222822    2.896833
groupby_multi_python                     104.568195  154.496574  105.849409  155.120993  104.800367
groupby_first                              6.722784    6.712580    4.733801    6.899405    4.831600
groupby_transform                        207.882404  210.259581  151.535606  210.865211  155.929804
groupby_multi_different_numpy_functions   22.729206   22.763395   15.735197   22.696781   15.843391

[stephenwlin]

OK, good to know it's not just my machine that has this issue.

I'm also not sure if it's bimodal with a large enough sample size,
actually..it seemed pretty (log-)normally distributed when I ran 100
iterations of reindexing tests. (This was before your multiple runs against
head additions, so I was looking at the log of the ratios between base and
target times rather than the raw times)

I pushed another update to test_perf, it now sets cpu affinity to protect againt cold cache surprises
due to thread migration on multicores and also does a gc collect between benchmarks, including
the libc trim voodoo from #2659.

using

 ./test_perf.sh --ncalls 1 --head --hrepeats 10 --outdf o.pickle

before and after definitely seems to have made an impact:

df=pd.load('o.pickle')
df=df[df.icol(0)>0.1]
df['max-min [% of mean]']=(df.max(1)-df.min(1))/df.mean(1)*100

before

Out[58]: 
                                      #0          #1  max-min [% of mean]
name                                                                     
frame_mult_no_ne               10.228872   11.081934             8.068553
frame_add                      10.586977   10.816097             5.836094
frame_multi_and_no_ne         107.260942   91.881990            32.076782
frame_add_no_ne                10.552168   11.853933            14.014677
frame_multi_and_st             45.034885   45.400143            30.600854
frame_mult_st                  10.640144   10.517120            16.973979
frame_multi_and                35.143137   35.255194            20.836927
frame_mult                     10.622978   10.655880             1.857611
frame_add_st                   10.926008   11.259079            11.381603
series_ctor_from_dict           2.861023    4.272938            44.420730
frame_ctor_nested_dict_int64   97.750902  142.644882            41.801547
frame_ctor_nested_dict         79.347849  115.172148            39.968815
frame_ctor_list_of_dict       102.699041  131.904125            32.164763
frame_boolean_row_select        0.298023    0.354052            52.197071
frame_reindex_both_axes         0.344992    0.579119            58.129294

after

In [59]: df[:15].iloc[:,[0,1,-1]]
Out[59]: 
                                      #0          #1  max-min [% of mean]
name                                                                     
frame_mult_no_ne               10.447979   10.501146             8.025565
frame_add                      10.565996   10.575056             4.184737
frame_multi_and_no_ne         105.782032   92.047930            15.303844
frame_add_no_ne                10.586023   10.318995             2.968311
frame_multi_and_st             45.217037   45.341015             3.462760
frame_mult_st                  10.675907   10.501862             4.573387
frame_multi_and                45.274973   45.464039             2.581288
frame_mult                     10.690928   10.643005             4.730513
frame_add_st                   10.578156   10.483980             2.867322
series_ctor_from_dict           2.854109    2.865076             2.026706
frame_ctor_nested_dict_int64  100.254774  102.154016             2.055916
frame_ctor_nested_dict         77.082872   78.242064             2.039485
frame_ctor_list_of_dict        99.193096  100.985050             5.003410
frame_boolean_row_select        0.237942    0.235081            45.588937
frame_reindex_both_axes         0.344038    0.356197             9.131816

There are still outliers in the data (and more in the entire dataset), but that's definitely
a marked improvement.

[jreback]

FYI The vbenchs like frame_add, frame_add_no_ne and such are using Numexpr (or not for comparison)
ne will try to use as many cores as u have. in theory this could cause affinity issues (as they mess with the caches), maybe should move these benches to the end?

Ok, good to know.

After disabling the ext4 journal commit interval and rerunning again 25 times,
here are all the vbenches that have more then 10% in the first col.
some of these are really not an issue, some are repeat offenders.
(frame_multi_and_no_ne and frame_reindex_axis1 for example)

Some of these are IO functions, which I'd expect to be a bit wonky.

@jreback: got any more insights?

                                        max-min / mean %       std         min         max
name                                                                                      
reindex_frame_level_align                      10.093073  0.025031    0.896613    0.991344
frame_reindex_axis0                            10.251804  0.022512    0.812372    0.898361
indexing_dataframe_boolean_no_ne               10.320826  3.102481  135.820309  150.233984
stats_rank_average                             10.432113  0.841592   28.482993   31.641324
frame_reindex_axis1                            10.799220  0.060237    2.086322    2.328316
groupby_last_float32                           11.341204  0.106584    4.812638    5.368948
frame_mult_no_ne                               11.934345  0.233660   10.227362   11.478027
groupby_indices                                11.951571  0.331111   10.515690   11.878411
indexing_dataframe_boolean_rows_object         12.426390  0.011096    0.468651    0.528018
frame_fancy_lookup_all                         12.527807  0.600790   22.018671   24.979353
query_store_table                              12.993687  0.156258    4.257679    4.854043
frame_drop_dup_na_inplace                      13.472561  0.087586    3.214677    3.657023
frame_multi_and_no_ne                          14.501948  2.623803   91.494640  104.933977
frame_boolean_row_select                       16.282358  0.005699    0.196298    0.230710
frame_reindex_upcast                           17.674176  0.855286   19.288619   23.082654
groupby_frame_cython_many_columns              19.232371  0.158495    4.280965    5.124966
frame_reindex_both_axes_ix                     19.647393  0.014742    0.408014    0.491619
join_dataframe_index_single_key_small          19.757504  0.487586    7.910967    9.624640
timeseries_period_downsample_mean              20.035858  0.323574    7.982969    9.604692
append_frame_single_homogenous                 21.374095  0.015835    0.231981    0.284990
read_store                                     23.731843  0.078693    1.738310    2.167940
groupby_simple_compress_timing                 27.898217  2.048904   36.627372   47.003667
reindex_multiindex                             31.810866  0.074761    1.168331    1.557271

[stephenwlin]

nice! that looks much better.

On Thu, Apr 4, 2013 at 8:56 PM, y-p notifications@github.com wrote:

I pushed another update to test_perf, it now sets cpu affinity to protect
againt cold cache surprises
due to thread migration on multicores and also does a gc collect between
benchmarks, including
the libc trim voodoo from #2659#2659
.

using

./test_perf.sh --ncalls 1 --head --hrepeats 10 --outdf o.pickle

before and after definitely seems to have made an impact:

df=pd.load('o.pickle')
df=df[df.icol(0)>0.1]
df['max-min [% of mean]']=(df.max(1)-df.min(1))/df.mean(1)*100

before

Out[58]:
#0 #1 max-min [% of mean]
name
frame_mult_no_ne 10.228872 11.081934 8.068553
frame_add 10.586977 10.816097 5.836094
frame_multi_and_no_ne 107.260942 91.881990 32.076782
frame_add_no_ne 10.552168 11.853933 14.014677
frame_multi_and_st 45.034885 45.400143 30.600854
frame_mult_st 10.640144 10.517120 16.973979
frame_multi_and 35.143137 35.255194 20.836927
frame_mult 10.622978 10.655880 1.857611
frame_add_st 10.926008 11.259079 11.381603
series_ctor_from_dict 2.861023 4.272938 44.420730
frame_ctor_nested_dict_int64 97.750902 142.644882 41.801547
frame_ctor_nested_dict 79.347849 115.172148 39.968815
frame_ctor_list_of_dict 102.699041 131.904125 32.164763
frame_boolean_row_select 0.298023 0.354052 52.197071
frame_reindex_both_axes 0.344992 0.579119 58.129294

after

In [59]: df[:15].iloc[:,[0,1,-1]]
Out[59]:
#0 #1 max-min [% of mean]
name
frame_mult_no_ne 10.447979 10.501146 8.025565
frame_add 10.565996 10.575056 4.184737
frame_multi_and_no_ne 105.782032 92.047930 15.303844
frame_add_no_ne 10.586023 10.318995 2.968311
frame_multi_and_st 45.217037 45.341015 3.462760
frame_mult_st 10.675907 10.501862 4.573387
frame_multi_and 45.274973 45.464039 2.581288
frame_mult 10.690928 10.643005 4.730513
frame_add_st 10.578156 10.483980 2.867322
series_ctor_from_dict 2.854109 2.865076 2.026706
frame_ctor_nested_dict_int64 100.254774 102.154016 2.055916
frame_ctor_nested_dict 77.082872 78.242064 2.039485
frame_ctor_list_of_dict 99.193096 100.985050 5.003410
frame_boolean_row_select 0.237942 0.235081 45.588937
frame_reindex_both_axes 0.344038 0.356197 9.131816

There are still outliers in the data (and more in the entire dataset), but
that's definitely
a marked improvement.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/3158#issuecomment-15933593
.

[jreback]

there is another source of variability here. the groupby timing in simple_compress is related to how random the input and this how many groups are formed.

any idea why it's the "no_ne" vbenches that are misbehaving?

[jreback]

they are really large (100k rows), prob cache missing a lot

[jreback]

also multi_ne are 3 Boolean ops, but because the first 2 ops are Boolean among random nums maybe 3rd op has more variance - just a guess

Actually I trimmed those down to 20000 because they were slowing down the
suite too much for doing this sort of testing.

knocking frame_multi_and_no_ne down to 5000/1000 rows doesn't do much.
worse if anything.

                       max-min / mean %       std     min       max
name                                                               
frame_multi_and_no_ne         54.453012  0.416195  4.7369  7.462978

                       max-min / mean %       std        min        max
name                                                                   
frame_multi_and_no_ne         46.707422  2.355675  24.782896  36.755085

At least it's now a breeze to test a hypothesis.