Operator Performance Regression on CPU

[roywei]

Follow up on dev list discussion:

https://lists.apache.org/thread.html/154ef1e4010671e7375c7a7cbedb413d5a4a3677321488440fb32a3a@%3Cdev.mxnet.apache.org%3E

We have found some operators to have performance regression using the operator benchmark module here:
https://github.com/apache/incubator-mxnet/tree/master/benchmark/opperf

@sandeep-krishnamurthy has helped to run the benchmark and this is the training mode result:
https://gist.github.com/sandeep-krishnamurthy/e0a2be893c8c4d484390c9c8813bdf50

The above result is using training mode (autograd.record()) and calculating both forward and backward time.

As most users use CPU for inference only, to further investigate the impact on inference I have run the scripts using inference mode

Please find the inference and training mode results here:
https://docs.google.com/spreadsheets/d/1_eezNWbrBAm3s3i6G1m0Rd3YYdTEnmKlYtn4klqdyN0/edit?usp=sharing

I have calculated the regression percentage and sorted them, thanks to @aaronmarkham for providing the first version.

Although there are variances on perf numbers between runs, we observe the following commonly used operators be slower consistently.

We need to look into them and fix if root caused.

• Dropout
• relu
• LeakyReLU
• dot
• element wise ops (mul, div, sub)
• broadcast ops (mul, sub)

Some ops regression seems only to happen on mxnet-mkl version (refer to 4th sheet of the google sheet)

Environment:

AWS C5.18xLarge
Deep Learning Base AMI (Ubuntu) Version 18.1
Python 3.6

MXNet versions:

with MKLDNN
pip install mxnet-mkl==1.5.0b20190627 
pip install mxnet-mkl==1.4.1

without MKLDNN
pip install mxnet==1.5.0b20190627
pip install mxnet==1.4.1

Note: nightly 20190627 contains the latest commit in v.1.5.x

Scripts:
https://github.com/apache/incubator-mxnet/tree/master/benchmark/opperf
Notes: you need to modify the scripts a bit to run

1. requires python 3.6, requires to add your scripts path to PYTHONPATH, follow instructions to run benchmark on all operators.
2. To run operators in inference mode, you need to set False at this line
   and change run_backward to False in all files under:
   https://github.com/apache/incubator-mxnet/tree/master/benchmark/opperf/nd_operations
   for example here.

[mxnet-label-bot]

Hey, this is the MXNet Label Bot.
Thank you for submitting the issue! I will try and suggest some labels so that the appropriate MXNet community members can help resolve it.
Here are my recommended labels: Performance

[roywei]

cc @PatricZhao @szha @ddavydenko

[roywei]

script command:
python incubator-mxnet/benchmark/opperf/opperf.py --output-format md --output-file mxnet-{version}-infer.md

raw script output:
https://drive.google.com/drive/folders/1OE-bedTFd-HN0Og6vW8XGWkswrRrdyW0?usp=sharing

[pengzhao-intel]

Maybe this is the same thing with #15430. @ciyongch is WIP

[ciyongch]

Yes, #15430 is also caused by op perf regression. I will try to reproduce the case and focus the inference firstly.

[ciyongch]

@roywei I've collected some performance data of Dropout, relu, and dot on C5.18xlarge, and saw some big run to run variance on dot and Dropout as below table without binding cores as table 1.
After binding cores to a socket via below command before running benchmarking, I got a stable and better results as table 2.

export KMP_AFFINITY=granularity=fine,noduplicates,compact,1,0
export OMP_NUM_THREADS=18

I ran 5 times with 10 warmup + 100 runs for each time. Not sure if you're setting the env variables when running the benchmark. And I suggest to re-run the ops for several times to see if it's a real degradation.

As for relu operator got worse perf on v1.5, I found v1.5 included the commit of c645591 (#14262), which added "IsNan(a)" check for data which introduced some overhead. Will add more data and more operator results later.

Table1

Operator	Avg Forward Time (ms) 1.4.1	Avg Forward Time (ms) 1.5.0	Regression	data shape
dot	0.1791	0.1576	12.0%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.2505	0.1146	54.3%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.1798	0.2531	-40.8%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.1529	0.2786	-82.2%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.4024	0.0763	81.0%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.1824	0.3437	-88.4%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
dot	0.1107	0.2491	-125.0%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
dot	0.4099	0.2401	41.4%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
dot	1.4348	0.2439	83.0%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
dot	0.3124	0.2922	6.5%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
Dropout	0.0551	0.0477	13.4%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}
Dropout	0.0446	0.0462	-3.6%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}
Dropout	0.078	0.0567	27.3%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}
Dropout	0.0311	0.0797	-156.3%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}
Dropout	0.3707	0.0671	81.9%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}

Table 2

Operator	Avg Forward Time (ms) 1.4.1	Avg Forward Time (ms) 1.5.0	Regression	data shape
dot	0.0079	0.0087	-10.1%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.0076	0.0089	-17.1%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.0079	0.009	-13.9%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.008	0.0093	-16.3%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.0078	0.0089	-14.1%	{'lhs': (1000, 1), 'rhs': (100, 1000), 'transpose_b': True, 'transpose_a': True}
dot	0.0946	0.0895	5.4%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
dot	0.0937	0.0889	5.1%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
dot	0.093	0.0895	3.8%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
dot	0.097	0.0898	7.4%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
dot	0.0908	0.089	2.0%	{'lhs': (1000, 10), 'rhs': (1000, 10), 'transpose_b': True}
Dropout	0.0238	0.0235	1.3%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}
Dropout	0.0244	0.0234	4.1%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}
Dropout	0.024	0.0234	2.5%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}
Dropout	0.024	0.0235	2.1%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}
Dropout	0.022	0.0234	-6.4%	{'mode': 'always', 'data': (10000, 10), 'p': 0.5}

[roywei]

Thanks @ciyongch , setting the environment variables did reduce the variances.
I have updated the document(1st sheet): https://docs.google.com/spreadsheets/d/1_eezNWbrBAm3s3i6G1m0Rd3YYdTEnmKlYtn4klqdyN0/edit#gid=196553607

With the current data Dot and Dropout is not a big concern now. Relu's regression is something we have to accept as otherwise it could lead to nans and bugs.

[ciyongch]

@roywei I looked at the table, except a few ops with big variances, most of the degraded ops listed in the table dropped into mshadow. I did some further analysis, and found that the performance regression is caused by the commit of 6e94643 (dmlc/mshadow#371), which changed the data type for index_t. Seems the quick fix in that PR didn't work for these ops, and a better solution is required for the type changing.

Here's some perf data collected on my local machine (SKX-8180), you can have a try on your platform :)

Operator	Avg Forward Time (ms) 1.4.1	Avg Forward Time (ms) 1.5.0	Regression	Avg Forward Time (ms) 1.5.0 (revert 6e94643)	Updated Regression	data shape
relu	0.0047	0.0107	127.7%	0.0057	21.3%	{'data': (10000, 1)}
relu	0.0065	0.0143	120.0%	0.005	-23.1%	{'data': (10000, 1)}
relu	0.005	0.0144	188.0%	0.0051	2.0%	{'data': (10000, 1)}
relu	0.0052	0.0115	121.2%	0.0066	26.9%	{'data': (10000, 1)}
relu	0.005	0.0138	176.0%	0.0061	22.0%	{'data': (10000, 1)}
logical_not	0.005	0.0221	342.0%	0.0057	14.0%	{'data': (10000, 1)}
logical_not	0.0051	0.0214	319.6%	0.0056	9.8%	{'data': (10000, 1)}
logical_not	0.0054	0.0215	298.1%	0.0056	3.7%	{'data': (10000, 1)}
logical_not	0.0051	0.0214	319.6%	0.0057	11.8%	{'data': (10000, 1)}
logical_not	0.0051	0.0216	323.5%	0.0056	9.8%	{'data': (10000, 1)}
softsign	0.0054	0.0166	207.4%	0.0059	9.3%	{'data': (10000, 1)}
softsign	0.0053	0.0166	213.2%	0.006	13.2%	{'data': (10000, 1)}
softsign	0.0058	0.0163	181.0%	0.006	3.4%	{'data': (10000, 1)}
softsign	0.0053	0.0162	205.7%	0.006	13.2%	{'data': (10000, 1)}
softsign	0.0054	0.0164	203.7%	0.0062	14.8%	{'data': (10000, 1)}

[TaoLv]

cc @apeforest

[sandeep-krishnamurthy]

Thanks @ciyongch for diving deep and help in identifying root cause of the issues.

Can you please help me understand why we see variance only for few operators without setting environment variables for KMP and OMP? Our users don't do these environment variable setup so is it something we need to worry about that these operators will perform badly and indeterministic without that setting?

[apeforest]

@TaoLv @ciyongch Thanks for the investigation. I will try to verify it on my machine.