10996 2017-01-31 18:00:16 +0000 test_ccache_tool taking too long on main AB 2017-08-03 14:24:28 +0000 1 1 10 QA/Testing Build Testing general 2.3 x86 Multiple RESOLVED FIXED Medium+ enhancement 2.4 M3 11417 10874 1 leonardo.sandoval.gonzalez leonardo.sandoval.gonzalez anibal.limon benjamin.esquivel jku joshuagloe mhalstead richard.purdie --- --- No (bug/feature does not impact docs) oldest_to_newest 70297 0 leonardo.sandoval.gonzalez 2017-01-31 18:00:16 +0000 Comparing to a local AB, the selftest test_ccache_tool on the buildtools test case is taking a considerably amount of time to finish it. There are some numbers comparing main versus local MAIN AB (columns are oe-selftest-build-id/time-in-seconds/testcase testname) 811.log 767.565 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool 807.log 1989.198 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool LOCAL AB (the same columns as above) oe-selftest-build-id/time-in-seconds/testcase testname 301.log 211.906 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool 312.log 108.776 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool 300.log 93.018 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool 70299 1 joshuagloe 2017-01-31 18:03:29 +0000 Which worker/host OS are the main AB runs on? Both are slower than the local AB, are they different OS workers? Or is there variance in the results for the same host OS? For completeness, which host OS are the local AB using? Are all results for the same host OS? 70300 2 leonardo.sandoval.gonzalez 2017-01-31 18:14:31 +0000 (In reply to comment #1) > Which worker/host OS are the main AB runs on? 312 HOSTNAME=opensuse132 301 HOSTNAME=centos7 300 HOSTNAME=fedora24 For the rest of the questions, Anibal is the person to answer these. 70301 3 leonardo.sandoval.gonzalez 2017-01-31 18:22:48 +0000 (In reply to comment #2) > (In reply to comment #1) > > Which worker/host OS are the main AB runs on? > > 312 HOSTNAME=opensuse132 > 301 HOSTNAME=centos7 > 300 HOSTNAME=fedora24 > > For the rest of the questions, Anibal is the person to answer these. Hit Save changes too fast! There are the host names for the main AB 811 HOSTNAME=centos7.osl.yoctoproject.org 807 HOSTNAME=opensuse132 So comparing apple with apples opensuse (807 versus 312) 807.log 1989.198 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool 312.log 108.776 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool and centos (811 versus 301) 811.log 767.565 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool 301.log 211.906 oeqa.selftest.buildoptions.ImageOptionsTests test_ccache_tool 70302 4 mhalstead 2017-01-31 19:27:55 +0000 Can you share the hardware profile of your local autobuilder? The main production autobuilder cluster is using fairly old components. Intel(R) Xeon(R) CPU X5690 x2 64GiB DDR3-1200 PERC 6p / 6 disks RAID-10 70351 5 anibal.limon 2017-02-01 21:51:37 +0000 (In reply to comment #4) > Can you share the hardware profile of your local autobuilder? > > The main production autobuilder cluster is using fairly old components. > > Intel(R) Xeon(R) CPU X5690 x2 > 64GiB DDR3-1200 > PERC 6p / 6 disks RAID-10 There are VM's upon physical machine's, Centos7/Fedora24: 14 cores attached of Intel(R) Xeon(R) CPU E5-2697 v2 @ 2.70GHz, 32 GiB RAM assigned, 1 TB disk using file Opensuse132: 16 cores attached of Intel(R) Xeon(R) CPU E5-2697 v2 @ 2.70GHz, 32 GiB RAM assigned, 1 TB disk using file 70352 6 mhalstead 2017-02-01 22:20:01 +0000 Thank you. That info is helpful. A quick glance indicates that while those CPUs are newer they aren't that much more capable. I'm not very familiar with test_ccache_tool. Can you provide an easy way to run just this test on an existing build so I can collect more stats? 70353 7 leonardo.sandoval.gonzalez 2017-02-01 22:42:00 +0000 (In reply to comment #6) > Thank you. That info is helpful. A quick glance indicates that while those > CPUs are newer they aren't that much more capable. > > I'm not very familiar with test_ccache_tool. Can you provide an easy way to > run just this test on an existing build so I can collect more stats? * clone poky * prepare the build env * run (with time cmd as prefix) the following test with oe-selftest $ time oe-selftest -r buildoptions.ImageOptionsTests test_ccache_tool this test builds ccache-native then uses it for building m4. 70354 8 leonardo.sandoval.gonzalez 2017-02-01 22:42:45 +0000 (In reply to comment #7) > (In reply to comment #6) > > Thank you. That info is helpful. A quick glance indicates that while those > > CPUs are newer they aren't that much more capable. > > > > I'm not very familiar with test_ccache_tool. Can you provide an easy way to > > run just this test on an existing build so I can collect more stats? > > * clone poky > * prepare the build env > * run (with time cmd as prefix) the following test with oe-selftest > > $ time oe-selftest -r buildoptions.ImageOptionsTests test_ccache_tool > > > this test builds ccache-native then uses it for building m4. Sorry for the spam, but the correct command is $ time oe-selftest -r buildoptions.ImageOptionsTests.test_ccache_tool 70369 9 joshuagloe 2017-02-02 15:51:57 +0000 Out of interest have we run the test on both GDC and public builders outside of the main build cycle (i.e. just using the command Leo pasted)? I wonder if the environment we use on the public AB is affecting the workload? Have we checked whether the ccache directory exists or not on each host? i.e. is the GDC builder faster because it has a ccache of objects to use? 70389 10 leonardo.sandoval.gonzalez 2017-02-02 16:37:33 +0000 (In reply to comment #9) > Out of interest have we run the test on both GDC and public builders outside > of the main build cycle (i.e. just using the command Leo pasted)? > I forced a build inside GDC, so I believe this counts as out of the build cycle. > I wonder if the environment we use on the public AB is affecting the > workload? Right, local build have less load. > > Have we checked whether the ccache directory exists or not on each host? > i.e. is the GDC builder faster because it has a ccache of objects to use? I will check that. In this area, comparing the autoconf steps, GDC does **not** have the following env variables (and main AB does) -CCACHE_CPP2 -CCACHE_HASHDIR I did a test on my local host, including these into the BB WHITELIST, and times did not change much, so apparently this is not affecting. 70405 11 mhalstead 2017-02-02 21:14:45 +0000 For reference the hardware at autobuilder.yocto.io is as follows. Intel(R) Xeon(R) CPU E5-2697 v3 x2 128GiB DDR4-2133 LSI-3108 8 disks in RAID-10 70407 12 leonardo.sandoval.gonzalez 2017-02-02 22:44:06 +0000 These are the times (real times obtained by the command 'time') when running the test 4 times in local (GDC) builders 4 matches for "real" in buffer: centos7 15:real 21m33.360s 36:real 1m40.560s 56:real 1m42.464s 76:real 1m38.078s 4 matches for "real" in buffer: opensuse132 15:real 35m39.357s 36:real 1m5.036s 56:real 1m6.491s 75:real 1m4.384s so for test n>1, opensuse beats centos by half a minute. Again, none of the builders have ccache installed. 70409 13 leonardo.sandoval.gonzalez 2017-02-02 22:59:13 +0000 (In reply to comment #12) > These are the times (real times obtained by the command 'time') when running > the test 4 times in local (GDC) builders > > 4 matches for "real" in buffer: centos7 > 15:real 21m33.360s > 36:real 1m40.560s > 56:real 1m42.464s > 76:real 1m38.078s > > 4 matches for "real" in buffer: opensuse132 > 15:real 35m39.357s > 36:real 1m5.036s > 56:real 1m6.491s > 75:real 1m4.384s > > so for test n>1, opensuse beats centos by half a minute. Again, none of the > builders have ccache installed. I forgot to include the times provided by the unittest module, similar to the time command but in seconds 8 matches for "OK" in buffer: centos7 3:2017-02-02 14:37:25 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (1268.120s) 24:2017-02-02 15:08:31 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (89.299s) 44:2017-02-02 15:12:42 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (91.301s) 64:2017-02-02 15:14:59 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (88.135s) 8 matches for "OK" in buffer: opensuse132 3:2017-02-02 13:16:24 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (2118.245s) 24:2017-02-02 13:55:26 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (57.971s) 44:2017-02-02 13:57:47 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (59.024s) 63:2017-02-02 14:00:05 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (57.413s) 70592 14 leonardo.sandoval.gonzalez 2017-02-09 16:27:53 +0000 Joshua, in case you have some time, could you execute the oe-selftest command on the main AB server? I tried access them without success so I need your help on this. 70663 15 joshuagloe 2017-02-13 16:41:51 +0000 (In reply to comment #14) > Joshua, in case you have some time, could you execute the oe-selftest > command on the main AB server? I tried access them without success so I need > your help on this. I did 3 runs on Fedora 24 in a clean build directory with shared state and download mirrors configured. $ time oe-selftest -r buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-13 16:07:13,892 - selftest - INFO - Running bitbake -e to get BBPATH 2017-02-13 16:07:15,335 - selftest - INFO - Checking that everything is in order before running the tests 2017-02-13 16:07:16,635 - selftest - WARNING - meta-selftest layer not found in BBLAYERS, adding it 2017-02-13 16:07:20,397 - selftest - INFO - Running bitbake -p 2017-02-13 16:07:37,586 - selftest - INFO - Loading tests from: oeqa.selftest.buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-13 16:07:37,608 - selftest - INFO - Adding: "include selftest.inc" in local.conf 2017-02-13 16:07:37,608 - selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf Running tests... ---------------------------------------------------------------------- 2017-02-13 16:07:37 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (798.632s) ---------------------------------------------------------------------- Ran 1 test in 798.633s OK Generating XML reports... 2017-02-13 16:20:56,242 - selftest - INFO - Finished 2017-02-13 16:20:56,257 - selftest - INFO - Removing the include from local.conf 2017-02-13 16:20:56,258 - selftest - INFO - Removing the include from bblayers.conf real 13m43.046s user 92m56.140s sys 12m51.515s --- $ time oe-selftest -r buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-13 16:29:15,968 - selftest - INFO - Running bitbake -e to get BBPATH 2017-02-13 16:29:17,344 - selftest - INFO - Checking that everything is in order before running the tests 2017-02-13 16:29:20,100 - selftest - INFO - Running bitbake -p 2017-02-13 16:29:23,892 - selftest - INFO - Loading tests from: oeqa.selftest.buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-13 16:29:23,931 - selftest - INFO - Adding: "include selftest.inc" in local.conf 2017-02-13 16:29:23,931 - selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf Running tests... ---------------------------------------------------------------------- 2017-02-13 16:29:23 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (62.654s) ---------------------------------------------------------------------- Ran 1 test in 62.655s OK Generating XML reports... 2017-02-13 16:30:26,587 - selftest - INFO - Finished 2017-02-13 16:30:26,588 - selftest - INFO - Removing the include from local.conf 2017-02-13 16:30:26,588 - selftest - INFO - Removing the include from bblayers.conf real 1m11.167s user 1m7.390s sys 0m12.196s --- $ time oe-selftest -r buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-13 16:37:24,552 - selftest - INFO - Running bitbake -e to get BBPATH 2017-02-13 16:37:25,903 - selftest - INFO - Checking that everything is in order before running the tests 2017-02-13 16:37:28,639 - selftest - INFO - Running bitbake -p 2017-02-13 16:37:32,470 - selftest - INFO - Loading tests from: oeqa.selftest.buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-13 16:37:32,472 - selftest - INFO - Adding: "include selftest.inc" in local.conf 2017-02-13 16:37:32,472 - selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf Running tests... ---------------------------------------------------------------------- 2017-02-13 16:37:32 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (62.656s) ---------------------------------------------------------------------- Ran 1 test in 62.657s OK Generating XML reports... 2017-02-13 16:38:35,130 - selftest - INFO - Finished 2017-02-13 16:38:35,130 - selftest - INFO - Removing the include from local.conf 2017-02-13 16:38:35,131 - selftest - INFO - Removing the include from bblayers.conf real 1m11.021s user 1m7.357s sys 0m12.284s 70665 16 leonardo.sandoval.gonzalez 2017-02-13 17:11:42 +0000 (In reply to comment #15) > (In reply to comment #14) > > Joshua, in case you have some time, could you execute the oe-selftest > > command on the main AB server? I tried access them without success so I need > > your help on this. > > I did 3 runs on Fedora 24 in a clean build directory with shared state and > download mirrors configured. Can you run the same tests on either an opensuse or centos worker? 70685 17 joshuagloe 2017-02-14 15:21:23 +0000 3 runs on openSUSE 13.2 in a clean build directory with shared state and download mirrors configured. --- $ time oe-selftest -r buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-14 14:30:29,761 - selftest - INFO - Running bitbake -e to get BBPATH 2017-02-14 14:30:32,320 - selftest - INFO - Checking that everything is in order before running the tests 2017-02-14 14:30:34,206 - selftest - WARNING - meta-selftest layer not found in BBLAYERS, adding it 2017-02-14 14:30:40,134 - selftest - INFO - Running bitbake -p 2017-02-14 14:31:07,368 - selftest - INFO - Loading tests from: oeqa.selftest.buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-14 14:31:07,378 - selftest - INFO - Adding: "include selftest.inc" in local.conf 2017-02-14 14:31:07,379 - selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf Running tests... ---------------------------------------------------------------------- 2017-02-14 14:31:07 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (1155.134s) ---------------------------------------------------------------------- Ran 1 test in 1155.136s OK Generating XML reports... 2017-02-14 14:50:22,517 - selftest - INFO - Finished 2017-02-14 14:50:22,517 - selftest - INFO - Removing the include from local.conf 2017-02-14 14:50:22,518 - selftest - INFO - Removing the include from bblayers.conf real 19m54.552s user 104m30.496s sys 11m1.792s --- $ time oe-selftest -r buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-14 15:12:22,897 - selftest - INFO - Running bitbake -e to get BBPATH 2017-02-14 15:12:24,885 - selftest - INFO - Checking that everything is in order before running the tests 2017-02-14 15:12:28,851 - selftest - INFO - Running bitbake -p 2017-02-14 15:12:34,268 - selftest - INFO - Loading tests from: oeqa.selftest.buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-14 15:12:34,271 - selftest - INFO - Adding: "include selftest.inc" in local.conf 2017-02-14 15:12:34,271 - selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf Running tests... ---------------------------------------------------------------------- 2017-02-14 15:12:34 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (93.254s) ---------------------------------------------------------------------- Ran 1 test in 93.256s OK Generating XML reports... 2017-02-14 15:14:07,528 - selftest - INFO - Finished 2017-02-14 15:14:07,529 - selftest - INFO - Removing the include from local.conf 2017-02-14 15:14:07,530 - selftest - INFO - Removing the include from bblayers.conf real 1m45.331s user 1m40.632s sys 0m12.056s --- $ time oe-selftest -r buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-14 15:17:52,831 - selftest - INFO - Running bitbake -e to get BBPATH 2017-02-14 15:17:54,837 - selftest - INFO - Checking that everything is in order before running the tests 2017-02-14 15:17:58,844 - selftest - INFO - Running bitbake -p 2017-02-14 15:18:04,302 - selftest - INFO - Loading tests from: oeqa.selftest.buildoptions.ImageOptionsTests.test_ccache_tool 2017-02-14 15:18:04,304 - selftest - INFO - Adding: "include selftest.inc" in local.conf 2017-02-14 15:18:04,305 - selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf Running tests... ---------------------------------------------------------------------- 2017-02-14 15:18:04 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (94.227s) ---------------------------------------------------------------------- Ran 1 test in 94.228s OK Generating XML reports... 2017-02-14 15:19:38,534 - selftest - INFO - Finished 2017-02-14 15:19:38,534 - selftest - INFO - Removing the include from local.conf 2017-02-14 15:19:38,535 - selftest - INFO - Removing the include from bblayers.conf real 1m46.388s user 1m41.212s sys 0m12.528s 70686 18 leonardo.sandoval.gonzalez 2017-02-14 15:46:25 +0000 (In reply to comment #17) > 3 runs on openSUSE 13.2 in a clean build directory with shared state and > download mirrors configured. > Thanks Joshua. So, stand-alone tests have expected times but in the context of --run-all-tests, there is something more going on that increases the times. In the other hand, there have been some changes on meta/lib/oeqa/selftest files that may give lower results, so I will check recent AB logs before proceeding. 70804 19 joshuagloe 2017-02-17 14:13:46 +0000 Leo, what's the status on this issue? It's currently assigned to me, should we reassign to you as you're doing the investigation. 70812 20 leonardo.sandoval.gonzalez 2017-02-17 14:44:19 +0000 (In reply to comment #19) > Leo, what's the status on this issue? > > It's currently assigned to me, should we reassign to you as you're doing the > investigation. Yes, assign it to me please, I will keep on this. 71683 21 jku 2017-03-24 09:36:33 +0000 This is still and issue with test_ccache_tool routinely taking 10 minutes (4% of the whole selftest runtime). 71694 22 leonardo.sandoval.gonzalez 2017-03-24 14:11:11 +0000 (In reply to comment #21) > This is still and issue with test_ccache_tool routinely taking 10 minutes > (4% of the whole selftest runtime). Right. Apparently the oe-selftest environment is affecting the test because standalone tests have much lower times as showed above. 72396 23 leonardo.sandoval.gonzalez 2017-04-12 17:58:06 +0000 (In reply to comment #21) > This is still and issue with test_ccache_tool routinely taking 10 minutes > (4% of the whole selftest runtime). Just did a query on this: curl -s https://autobuilder.yoctoproject.org/main/builders/nightly-oe-selftest/builds/870/steps/Running%20oe-selftest/logs/stdio/text | grep test_ccache_tool 2017-04-11 22:52:44 - test_ccache_tool (oeqa.selftest.buildoptions.ImageOptionsTests) ... OK (3078.308s) so 30378s/60s=51minutes so almost an hour to complete! 72860 24 leonardo.sandoval.gonzalez 2017-04-26 14:54:07 +0000 The unit test introduces the INHERIT += "ccache" thus invalidating checksums or most (all?) recipes depending on m4 (after INHERIT, bitbake -c compile -f m4 is done), thus this is the reason of such long times observed. 73884 25 leonardo.sandoval.gonzalez 2017-06-08 13:53:04 +0000 Dependency is targeted for M2 so setting M3 for this bug. 75611 26 leonardo.sandoval.gonzalez 2017-08-03 14:24:28 +0000 Two AB filed with and without Ross patches and these confirm the fix without Ross set of patches (poky commit 8839ed1620c80f3c4a806c096e97d25c68d6d64e) 2017-08-02 15:08:16,004 - oe-selftest - INFO - test_ccache_tool (buildoptions.ImageOptionsTests) ... OK (1138.259s) with Ross set of patches (poky commit 173760abc66580e21b36eac3a591847e0d3e91f4) 2017-08-02 14:36:04,415 - oe-selftest - INFO - test_ccache_tool ( buildoptions.ImageOptionsTests) ... OK (101.112s) so ~ 10x speed-up. Just one minor detail: both builds were done on separate machines with similar HW but different OS; a better test would be on a single machine.