{"thread":{"id":"46109","subject":"[PATCH] test-lib: add ability to cap the runtime of tests","startedAt":"2017-06-03T22:13:53Z","lastAt":"2017-06-08T01:00:01Z","messageCount":12,"participants":["Ævar Arnfjörð Bjarmason","Junio C Hamano","Christian Couder","Lars Schneider","Stefan Beller","Jeff King","Ramsay Jones"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"321486","messageId":"20170603221335.3038-1-avarab@gmail.com","threadId":"46109","inReplyTo":null,"subject":"[PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2017-06-03T22:13:35Z","receivedAt":"2017-06-03T22:13:53Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"Add a GIT_TEST_TIMEOUT environment variable which optimistically sets\nan approximate upper limit on how long any one test is allowed to\nrun.\n\nOnce the timeout is exceeded all remaining tests are skipped, no\nattempt is made to stop a long running test in-progress, or deal with\nthe edge case of the epoch changing the epoch from under us by\ne.g. ntpd.\n\nOn my machine median runtime for a test is around 150ms, but 8 tests\ntake more than 10 seconds to run, with t3404-rebase-interactive.sh\ntaking 18 seconds.\n\nOn a machine with a large number of cores these long-tail tests become\nthe limiting factor in how long it takes to run the entire test suite,\neven if it's run with \"prove --state=slow,save\". This is because the\nfirst long-running tests started at the very beginning will still be\nrunning by the time the rest of the test suite finishes.\n\nSpeeding up the test suite by simply cataloging and skipping tests\nthat take longer than N seconds is a hassle to maintain, and entirely\nskips some tests which would be nice to at least partially run,\ne.g. instead of entirely skipping t3404-rebase-interactive.sh we can\nrun it for N seconds and get at least some \"git rebase -i\" test\ncoverage in a fast test run.\n\nOn a 56 core Xeon E5-2690 v4 @ 2.60GHz the runtime for the test suite\nis cut in half with GIT_TEST_TIMEOUT=10 under prove -j56\nt[0-9]*.sh. Approximate time to run all the tests with various\nGIT_TEST_TIMEOUT settings[1]:\n\n    N/A     30s\n    20      20s\n    10      15s\n    5       12s\n    1       12s\n\nSetting a timeout lower than 5-10 seconds or so starts to reach\ndiminishing returns, e.g. t7063-status-untracked-cache.sh always takes\nat least 6 seconds to run since it's blocking on a single\n\"update-index --test-untracked-cache\" command. So there's room for\nimprovement, but this simple facility gives us most of the benefits.\n\nThe number of tests on the aforementioned machine which are run with\nthe various timeouts[2]:\n\n    N/A     16261\n    20      16037\n    10      14972\n    5       13952\n    1       8409\n\nWhile running with a timeout of 10 seconds cuts the runtime in half,\nover 92% of the tests are still run. The test coverage is higher than\nthat number indicates, just taking into account the many similar tests\nt0027-auto-crlf.sh runs brings it up to 95%.\n\n1. for t in '' 20 10; do printf \"%s\\t\" $t && (time GIT_TEST_TIMEOUT=$t prove -j$(parallel --number-of-cores) --state=slow,save t[0-9]*.sh) 2>&1 | grep ^real | grep -E -o '[0-9].*'; done\n2. for t in '' 20 10 5 1; do printf \"%s\\t\" $t && (time GIT_TEST_TIMEOUT=$t prove -j$(parallel --number-of-cores) --state=slow,save -v t[0-9]*.sh) 2>&1 | grep -e ^real -e '^1\\.\\.' | sed 's/^1\\.\\.//' | awk '{s+=$1} END {print s}'; done\n\nSigned-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>\n---\n t/test-lib.sh | 20 +++++++++++++++++++-\n 1 file changed, 19 insertions(+), 1 deletion(-)\n\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 4936725c67..0353e73873 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -15,6 +15,13 @@\n # You should have received a copy of the GNU General Public License\n # along with this program.  If not, see http://www.gnu.org/licenses/ .\n \n+# If we have a set max runtime record the startup time before anything\n+# else is done.\n+if test -n \"$GIT_TEST_TIMEOUT\"\n+then\n+\tTEST_STARTUP_TIME=$(date +%s)\n+fi\n+\n # Test the binaries we have just built.  The tests are kept in\n # t/ subdirectory and are run in 'trash directory' subdirectory.\n if test -z \"$TEST_DIRECTORY\"\n@@ -689,11 +696,22 @@ test_skip () {\n \t\tto_skip=t\n \t\tskipped_reason=\"--run\"\n \tfi\n+\tif test -n \"$GIT_TEST_TIMEOUT\" &&\n+\t\ttest \"$(($(date +%s) - $TEST_STARTUP_TIME))\" -ge \"$GIT_TEST_TIMEOUT\"\n+\tthen\n+\t\tto_skip=all\n+\t\tskipped_reason=\"Exceeded GIT_TEST_TIMEOUT in runtime\"\n+\tfi\n \n \tcase \"$to_skip\" in\n-\tt)\n+\tall|t)\n \t\tsay_color skip >&3 \"skipping test: $@\"\n \t\tsay_color skip \"ok $test_count # skip $1 ($skipped_reason)\"\n+\t\tif test \"$to_skip\" = all\n+\t\tthen\n+\t\t\tskip_all=\"$skipped_reason\"\n+\t\t\ttest_done\n+\t\tfi\n \t\t: true\n \t\t;;\n \t*)\n-- \n2.13.0.506.g27d5fe0cd\n\n"},{"id":"321492","messageId":"xmqqa85owq3b.fsf@gitster.mtv.corp.google.com","threadId":"46109","inReplyTo":"20170603221335.3038-1-avarab@gmail.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-06-04T00:31:36Z","receivedAt":"2017-06-04T00:31:43Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:\n\n> Speeding up the test suite by simply cataloging and skipping tests\n> that take longer than N seconds is a hassle to maintain, and entirely\n> skips some tests which would be nice to at least partially run,\n> e.g. instead of entirely skipping t3404-rebase-interactive.sh we can\n> run it for N seconds and get at least some \"git rebase -i\" test\n> coverage in a fast test run.\n\nI'd be more supportive to the former approach in the longer run for\ntwo reasons.\n\nIs it even safe to stop a test in the middle?  Won't we leave\nleftover server processes, for example?\n\n    I see start_httpd at least sets up \"trap\" to call stop_httpd\n    when the shell exits, so HTTP testing via lib-httpd.sh may be\n    safe.  I do not know about other network-y tests, though.\n\nGranted, when a test fails, we already have the same problem, but\nthen we'd go in and investigate, and the first thing we notice would\nbe that the old leftover server instance is holding onto the port to\nprevent the attempt to re-run the test from running, which then we'd\nkill.  But with this option, the user is not even made aware of\ntests being killed in the middle.\n\n> While running with a timeout of 10 seconds cuts the runtime in half,\n> over 92% of the tests are still run. The test coverage is higher than\n> that number indicates, just taking into account the many similar tests\n> t0027-auto-crlf.sh runs brings it up to 95%.\n\nI certainly understand that but in the longer term, I'd prefer the\napproach to call out an overly large test.  That will hopefully\nmotivate us to split it (or speed up the thing) to help folks on\nmany-core machines.\n\nI am afraid that the proposed change will disincentivize that by\nsweeping the problematic ones under the rug.  Perhaps you can\ncollect what tests are terminated in the middle because they run for\ntoo long and show the list of them at the end, or something?\n\nAlso, I thought that it was a no-no to say \"to_skil=all\" with\nskipped-reason in the middle of a test when the test is run under\nprove?\n\nOh, by the way, is \"date +%s\" even portable?  I thought not.\n\n\n\n"},{"id":"321497","messageId":"CACBZZX5_AYOXZMrgVZuERzOdzntw0ec36bKS5mcKT510cC3Y2g@mail.gmail.com","threadId":"46109","inReplyTo":"xmqqa85owq3b.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2017-06-04T07:29:22Z","receivedAt":"2017-06-04T07:37:37Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"On Sun, Jun 4, 2017 at 2:31 AM, Junio C Hamano <gitster@pobox.com> wrote:\n> Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:\n>\n>> Speeding up the test suite by simply cataloging and skipping tests\n>> that take longer than N seconds is a hassle to maintain, and entirely\n>> skips some tests which would be nice to at least partially run,\n>> e.g. instead of entirely skipping t3404-rebase-interactive.sh we can\n>> run it for N seconds and get at least some \"git rebase -i\" test\n>> coverage in a fast test run.\n>\n> I'd be more supportive to the former approach in the longer run for\n> two reasons.\n>\n> Is it even safe to stop a test in the middle?  Won't we leave\n> leftover server processes, for example?\n>\n>     I see start_httpd at least sets up \"trap\" to call stop_httpd\n>     when the shell exits, so HTTP testing via lib-httpd.sh may be\n>     safe.  I do not know about other network-y tests, though.\n\nWhen this flag is in effect and you run into the timeout the code is\nsemantically equivalent to not running subsequent test_expect_*\nblocks, things like the trap in lib-httpd.sh will still run, so will\ntest_when_finished.\n\nUnless we have some test killing a daemon in a test_expect_success\nblock later in the test this'll work as intended.\n\n> Granted, when a test fails, we already have the same problem, but\n> then we'd go in and investigate, and the first thing we notice would\n> be that the old leftover server instance is holding onto the port to\n> prevent the attempt to re-run the test from running, which then we'd\n> kill.  But with this option, the user is not even made aware of\n> tests being killed in the middle.\n>\n>> While running with a timeout of 10 seconds cuts the runtime in half,\n>> over 92% of the tests are still run. The test coverage is higher than\n>> that number indicates, just taking into account the many similar tests\n>> t0027-auto-crlf.sh runs brings it up to 95%.\n>\n> I certainly understand that but in the longer term, I'd prefer the\n> approach to call out an overly large test.  That will hopefully\n> motivate us to split it (or speed up the thing) to help folks on\n> many-core machines.\n\nThe reason I didn't document this in t/README was because I thought it\nmade sense to have this as a mostly hidden feature that end users\nwouldn't be tempted to fiddle with, but would be useful to someone\ndoing git development.\n\nRealistically I'm going to submit this patch, I'm not going to take\nthe much bigger project of refactoring the entire test suite so that\nno test runs under N second, and of course any such refactoring can\nonly aim for a fixed instead of dynamic N.\n\nThe point of this change is that I can replace running e.g. \"prove\nt[0-9]*{grep,log}*.sh\" with just running the full test suite every\ntime, since 30s is noticeably slow during regular hacking but once\nit's down to 15s it's perceptively fast enough.\n\nReading between the lines in your reply, I think you're afraid that\nregular users just testing git out will start using this, as opposed\nto power user developers who understand the trade-offs. I think that's\nmostly mitigated by not documenting it in t/README, but I could amend\nthe patch to add some scary commend to test-lib.sh as well.\n\n> I am afraid that the proposed change will disincentivize that by\n> sweeping the problematic ones under the rug.  Perhaps you can\n> collect what tests are terminated in the middle because they run for\n> too long and show the list of them at the end, or something?\n\nThis change incentivizes  me to be regularly running a larger % of the\nfull test suite.\n\nCollecting the skipped ones is easy enough to do with a grep + for\nloop, so I don't think it's worth making the implementation more\ncomplex to occasionally answer the question of how many tests were\nskipped due to running into the timeout:\n\n$ rm .prove; for t in 20 10 5 1; do printf \"%s\\t\" $t && (time\nGIT_TEST_TIMEOUT=$t prove -j$(parallel --number-of-cores)\n--state=slow,save -v t[0-9]*.sh) 2>&1 | grep -c \"Exceeded\nGIT_TEST_TIMEOUT\"; done\nrm: cannot remove ‘.prove’: No such file or directory\n20      4\n10      36\n5       80\n1       509\n\nOf course that gives you \"how many tests had skipped tests\", now how\nmany test_expect_* blocks were skipped. An earlier WIP version of this\ndid the former, but e.g. running the rest of t0027-auto-crlf.sh took\nmany seconds just do spew out hundreds/thousands of lines in a shell\nloop emitting \"skip\" lines, so I went with the to_skip=all\nimplementation.\n\n> Also, I thought that it was a no-no to say \"to_skil=all\" with\n> skipped-reason in the middle of a test when the test is run under\n> prove?\n\nTAP has two main modes of operation, you can either declare that\nyou're going to run N tests in advance and then you must run N, this\nmakes prove report progress on your tests as they run.\n\nOr you can just run in a mode where you stream out however many tests\nyou're going to run as you go along, and then print \"1..NUM_TESTS\" at\nthe end.\n\nWe use the latter, so we can abort the entire test suite at any time\nwith test_done, that's what this change does.\n\n> Oh, by the way, is \"date +%s\" even portable?  I thought not.\n\nThe lib-git-p4.sh lib says not, and shells out to python's time() is a\nworkaround, I could replace this with perl -e 'print time', but\nthought it wasn't worth bothering with for an obscure optional feature\nlike this.\n\nSince 6a9d16a0a8 (\"filter-branch: add passed/remaining seconds on\nprogress\", 2015-09-07) git-filter-branch relies on `date +%s`.\n\nI suspect Solaris users are just setting a GNU/updated toolpath in\ntheir $PATH, and worrying about this isn't worth bothering with,\nespecially for this sort of thing.\n"},{"id":"321517","messageId":"xmqqefuzurj5.fsf@gitster.mtv.corp.google.com","threadId":"46109","inReplyTo":"CACBZZX5_AYOXZMrgVZuERzOdzntw0ec36bKS5mcKT510cC3Y2g@mail.gmail.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-06-05T01:55:42Z","receivedAt":"2017-06-05T01:55:51Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes:\n\n>> I certainly understand that but in the longer term, I'd prefer the\n>> approach to call out an overly large test.  That will hopefully\n>> motivate us to split it (or speed up the thing) to help folks on\n>> many-core machines.\n>\n> The reason I didn't document this in t/README was because I thought it\n> made sense to have this as a mostly hidden feature that end users\n> wouldn't be tempted to fiddle with, but would be useful to someone\n> doing git development.\n>\n> Realistically I'm going to submit this patch, I'm not going to take\n> the much bigger project of refactoring the entire test suite so that\n> no test runs under N second, and of course any such refactoring can\n> only aim for a fixed instead of dynamic N.\n\nI do not expect any single person to tackle the splitting.  I just\nwished that a patch inspired by this patch (or better yet, a new\nversion of this patch) made the tail end of \"make test\" output to\nread like this:\n\n   ...\n   [18:32:44] t9400-git-cvsserver-server.sh ...... ok    18331 ms\n   [18:32:49] t9402-git-cvsserver-refs.sh ........ ok    22902 ms\n   [18:32:49] t9200-git-cvsexportcommit.sh ....... ok    25163 ms\n   [18:32:51]\n   All tests successful.\n   Files=785, Tests=16928, 122 wallclock secs ( ...\n   Result: PASS\n\n   * The following tests took longer than 15 seconds to run.  We\n     may want to look into splitting them into smaller files.\n\n   t3404-rebase-interactive.sh ...    19 secs\n   t9001-send-email.sh ...........    22 secs\n   t9402-git-cvsserver-refs.sh ...    22 secs\n   t9200-git-cvsexportcommit.sh ..    25 secs\n\nwhen the hidden feature is _not_ used, so that wider set of people\nwill be forced to see that some tests take inordinate amount of\ntime, and entice at least some of them to look into it.\n\n> Collecting the skipped ones is easy enough to do with a grep + for\n> loop, so I don't think it's worth making the implementation more\n> complex to occasionally answer the question of how many tests were\n> skipped due to running into the timeout\n\n\"Easy enough\" and \"made to stand out so _NO_ effort is needed to\nsee\" are very different things.\n\n> Or you can just run in a mode where you stream out however many tests\n> you're going to run as you go along, and then print \"1..NUM_TESTS\" at\n> the end.\n>\n> We use the latter, so we can abort the entire test suite at any time\n> with test_done, that's what this change does.\n\ncf. bf4b7219 (\"test-lib.sh: Add check for invalid use of 'skip_all'\nfacility\", 2012-09-01)\n\n>> Oh, by the way, is \"date +%s\" even portable?  I thought not.\n>\n> The lib-git-p4.sh lib says not, and shells out to python's time() is a\n> workaround, I could replace this with perl -e 'print time', but\n> thought it wasn't worth bothering with for an obscure optional feature\n> like this.\n\nLet's do the right thing, because doing so is easy.\n\nI personally think that filter-branch being broken is not noticed\nonly because it is not very often used, as opposed to that we want\nto encourage those who are following along with us, especially those\nwho are on minority platforms, to run our tests every day.  Let's\nnot spread sloppyness unnecessarily.\n"},{"id":"321522","messageId":"CAP8UFD3-=sDQ2PEExLq_A3v5d8w8PJ1aLgBNP725mGHzocuqqQ@mail.gmail.com","threadId":"46109","inReplyTo":"xmqqefuzurj5.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Christian Couder","fromEmail":"christian.couder@gmail.com","sentAt":"2017-06-05T05:48:49Z","receivedAt":"2017-06-05T05:48:57Z","isPatch":true,"sender":{"key":"christian.couder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/208954?v=4"},"body":"On Mon, Jun 5, 2017 at 3:55 AM, Junio C Hamano <gitster@pobox.com> wrote:\n> Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes:\n>\n>> Realistically I'm going to submit this patch, I'm not going to take\n>> the much bigger project of refactoring the entire test suite so that\n>> no test runs under N second, and of course any such refactoring can\n>> only aim for a fixed instead of dynamic N.\n>\n> I do not expect any single person to tackle the splitting.  I just\n> wished that a patch inspired by this patch (or better yet, a new\n> version of this patch) made the tail end of \"make test\" output to\n> read like this:\n>\n>    ...\n>    [18:32:44] t9400-git-cvsserver-server.sh ...... ok    18331 ms\n>    [18:32:49] t9402-git-cvsserver-refs.sh ........ ok    22902 ms\n>    [18:32:49] t9200-git-cvsexportcommit.sh ....... ok    25163 ms\n>    [18:32:51]\n>    All tests successful.\n>    Files=785, Tests=16928, 122 wallclock secs ( ...\n>    Result: PASS\n>\n>    * The following tests took longer than 15 seconds to run.  We\n>      may want to look into splitting them into smaller files.\n>\n>    t3404-rebase-interactive.sh ...    19 secs\n>    t9001-send-email.sh ...........    22 secs\n>    t9402-git-cvsserver-refs.sh ...    22 secs\n>    t9200-git-cvsexportcommit.sh ..    25 secs\n>\n> when the hidden feature is _not_ used, so that wider set of people\n> will be forced to see that some tests take inordinate amount of\n> time, and entice at least some of them to look into it.\n\nI wonder if splitting tests would make a good GSoC microproject for next year.\n"},{"id":"321532","messageId":"1D06FFF7-C36D-4072-8B37-4C9DC45E4442@gmail.com","threadId":"46109","inReplyTo":"CACBZZX5_AYOXZMrgVZuERzOdzntw0ec36bKS5mcKT510cC3Y2g@mail.gmail.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Lars Schneider","fromEmail":"larsxschneider@gmail.com","sentAt":"2017-06-05T13:17:25Z","receivedAt":"2017-06-05T13:19:16Z","isPatch":true,"sender":{"key":"larsxschneider@gmail.com","avatar":"https://avatars.githubusercontent.com/u/477434?v=4"},"body":"\n> On 04 Jun 2017, at 09:29, Ævar Arnfjörð Bjarmason <avarab@gmail.com> wrote:\n> \n> On Sun, Jun 4, 2017 at 2:31 AM, Junio C Hamano <gitster@pobox.com> wrote:\n>> Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:\n>> \n>>> Speeding up the test suite by simply cataloging and skipping tests\n>>> that take longer than N seconds is a hassle to maintain, and entirely\n>>> skips some tests which would be nice to at least partially run,\n>>> e.g. instead of entirely skipping t3404-rebase-interactive.sh we can\n>>> run it for N seconds and get at least some \"git rebase -i\" test\n>>> coverage in a fast test run.\n>> \n>> I'd be more supportive to the former approach in the longer run for\n>> two reasons.\n>> \n>> Is it even safe to stop a test in the middle?  Won't we leave\n>> leftover server processes, for example?\n>> \n>>    I see start_httpd at least sets up \"trap\" to call stop_httpd\n>>    when the shell exits, so HTTP testing via lib-httpd.sh may be\n>>    safe.  I do not know about other network-y tests, though.\n> \n> When this flag is in effect and you run into the timeout the code is\n> semantically equivalent to not running subsequent test_expect_*\n> blocks, things like the trap in lib-httpd.sh will still run, so will\n> test_when_finished.\n> \n> Unless we have some test killing a daemon in a test_expect_success\n> block later in the test this'll work as intended.\n> \n>> Granted, when a test fails, we already have the same problem, but\n>> then we'd go in and investigate, and the first thing we notice would\n>> be that the old leftover server instance is holding onto the port to\n>> prevent the attempt to re-run the test from running, which then we'd\n>> kill.  But with this option, the user is not even made aware of\n>> tests being killed in the middle.\n>> \n>>> While running with a timeout of 10 seconds cuts the runtime in half,\n>>> over 92% of the tests are still run. The test coverage is higher than\n>>> that number indicates, just taking into account the many similar tests\n>>> t0027-auto-crlf.sh runs brings it up to 95%.\n>> \n>> I certainly understand that but in the longer term, I'd prefer the\n>> approach to call out an overly large test.  That will hopefully\n>> motivate us to split it (or speed up the thing) to help folks on\n>> many-core machines.\n> \n> The reason I didn't document this in t/README was because I thought it\n> made sense to have this as a mostly hidden feature that end users\n> wouldn't be tempted to fiddle with, but would be useful to someone\n> doing git development.\n> \n> Realistically I'm going to submit this patch, I'm not going to take\n> the much bigger project of refactoring the entire test suite so that\n> no test runs under N second, and of course any such refactoring can\n> only aim for a fixed instead of dynamic N.\n> \n> The point of this change is that I can replace running e.g. \"prove\n> t[0-9]*{grep,log}*.sh\" with just running the full test suite every\n> time, since 30s is noticeably slow during regular hacking but once\n> it's down to 15s it's perceptively fast enough.\n> \n> Reading between the lines in your reply, I think you're afraid that\n> regular users just testing git out will start using this, as opposed\n> to power user developers who understand the trade-offs. I think that's\n> mostly mitigated by not documenting it in t/README, but I could amend\n> the patch to add some scary commend to test-lib.sh as well.\n\nMaybe I am wrong here, but I would be very surprised if a \"regular user\"\nwho does not dive into the Git source code would run the tests at all.\n\nPlus, wouldn't it make sense to mark tests that run longer than 10sec \non average hardware with \"GIT_TEST_LONG\"? Wouldn't that solve your\nproblem in a nice way?\n\nWe could use TravisCI as baseline for \"average hardware\":\nhttps://travis-ci.org/git/git/jobs/239451918\n\n- Lars\n\n\n"},{"id":"321543","messageId":"CACBZZX5FP_jxXaT+NW8g2JqH89iYajHPjHhxCj=_vWnkxZ=rYQ@mail.gmail.com","threadId":"46109","inReplyTo":"1D06FFF7-C36D-4072-8B37-4C9DC45E4442@gmail.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2017-06-05T18:15:18Z","receivedAt":"2017-06-05T18:15:45Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"On Mon, Jun 5, 2017 at 3:17 PM, Lars Schneider <larsxschneider@gmail.com> wrote:\n>\n>> On 04 Jun 2017, at 09:29, Ævar Arnfjörð Bjarmason <avarab@gmail.com> wrote:\n>>\n>> On Sun, Jun 4, 2017 at 2:31 AM, Junio C Hamano <gitster@pobox.com> wrote:\n>>> Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:\n>>>\n>>>> Speeding up the test suite by simply cataloging and skipping tests\n>>>> that take longer than N seconds is a hassle to maintain, and entirely\n>>>> skips some tests which would be nice to at least partially run,\n>>>> e.g. instead of entirely skipping t3404-rebase-interactive.sh we can\n>>>> run it for N seconds and get at least some \"git rebase -i\" test\n>>>> coverage in a fast test run.\n>>>\n>>> I'd be more supportive to the former approach in the longer run for\n>>> two reasons.\n>>>\n>>> Is it even safe to stop a test in the middle?  Won't we leave\n>>> leftover server processes, for example?\n>>>\n>>>    I see start_httpd at least sets up \"trap\" to call stop_httpd\n>>>    when the shell exits, so HTTP testing via lib-httpd.sh may be\n>>>    safe.  I do not know about other network-y tests, though.\n>>\n>> When this flag is in effect and you run into the timeout the code is\n>> semantically equivalent to not running subsequent test_expect_*\n>> blocks, things like the trap in lib-httpd.sh will still run, so will\n>> test_when_finished.\n>>\n>> Unless we have some test killing a daemon in a test_expect_success\n>> block later in the test this'll work as intended.\n>>\n>>> Granted, when a test fails, we already have the same problem, but\n>>> then we'd go in and investigate, and the first thing we notice would\n>>> be that the old leftover server instance is holding onto the port to\n>>> prevent the attempt to re-run the test from running, which then we'd\n>>> kill.  But with this option, the user is not even made aware of\n>>> tests being killed in the middle.\n>>>\n>>>> While running with a timeout of 10 seconds cuts the runtime in half,\n>>>> over 92% of the tests are still run. The test coverage is higher than\n>>>> that number indicates, just taking into account the many similar tests\n>>>> t0027-auto-crlf.sh runs brings it up to 95%.\n>>>\n>>> I certainly understand that but in the longer term, I'd prefer the\n>>> approach to call out an overly large test.  That will hopefully\n>>> motivate us to split it (or speed up the thing) to help folks on\n>>> many-core machines.\n>>\n>> The reason I didn't document this in t/README was because I thought it\n>> made sense to have this as a mostly hidden feature that end users\n>> wouldn't be tempted to fiddle with, but would be useful to someone\n>> doing git development.\n>>\n>> Realistically I'm going to submit this patch, I'm not going to take\n>> the much bigger project of refactoring the entire test suite so that\n>> no test runs under N second, and of course any such refactoring can\n>> only aim for a fixed instead of dynamic N.\n>>\n>> The point of this change is that I can replace running e.g. \"prove\n>> t[0-9]*{grep,log}*.sh\" with just running the full test suite every\n>> time, since 30s is noticeably slow during regular hacking but once\n>> it's down to 15s it's perceptively fast enough.\n>>\n>> Reading between the lines in your reply, I think you're afraid that\n>> regular users just testing git out will start using this, as opposed\n>> to power user developers who understand the trade-offs. I think that's\n>> mostly mitigated by not documenting it in t/README, but I could amend\n>> the patch to add some scary commend to test-lib.sh as well.\n>\n> Maybe I am wrong here, but I would be very surprised if a \"regular user\"\n> who does not dive into the Git source code would run the tests at all.\n>\n> Plus, wouldn't it make sense to mark tests that run longer than 10sec\n> on average hardware with \"GIT_TEST_LONG\"? Wouldn't that solve your\n> problem in a nice way?\n>\n> We could use TravisCI as baseline for \"average hardware\":\n> https://travis-ci.org/git/git/jobs/239451918\n\nThere would be no point in marking the tests that take over 10s on\naverage hardware, and it's busywork to maintain those markers.\n\nAlso, as the numbers quoted in my patch show 10s is an arbitrary sweet\nspot on that particular box, maybe it's 20s on some other hardware, or\n5s if someone produces a 84 core box.\n\nThis patch is only something someone who has exceptional hardware\nwould care about. These long running tests in question don't have much\nimpact on the total CPU time spent on the test suite, the problem,\nsuch as it is, is that they're not split up into more files, and thus\nin a sufficiently beefy machine the entirety of the rest of the\nparallel test suite can be over by the time these stragglers finish.\n\nThat's never going to be a problem on a less beefy machine with\n--state=slow,save, since the 30s test is going to be long over by the\ntime the rest of the tests run.\n\nCutting down on these long tail tests allows me to e.g. replace this:\n\n    git rebase -i --exec '(make -j56 all && cd t && prove -j56 <some\nlimited glob>)'\n\nWith a glob that runs the entire test suite, with the rebase only\ntaking marginally longer in most cases while getting much better test\ncoverage than I'd otherwise bother with.\n"},{"id":"321551","messageId":"CAGZ79kbXS83s1tizFm1y_uZZ9CYDa0zoHWH4U3HK=3-Bp5XbUg@mail.gmail.com","threadId":"46109","inReplyTo":"CAP8UFD3-=sDQ2PEExLq_A3v5d8w8PJ1aLgBNP725mGHzocuqqQ@mail.gmail.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2017-06-05T18:56:12Z","receivedAt":"2017-06-05T18:56:17Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"On Sun, Jun 4, 2017 at 10:48 PM, Christian Couder\n<christian.couder@gmail.com> wrote:\n>> when the hidden feature is _not_ used, so that wider set of people\n>> will be forced to see that some tests take inordinate amount of\n>> time, and entice at least some of them to look into it.\n>\n> I wonder if splitting tests would make a good GSoC microproject for next year.\n\nThat is an interesting thought.\n\nIt scales pretty well IMHO.\n(Have a good student that works quickly\n-> we'll have very modular tests at the end,\nhave a student doing a-ok\n-> at least parts are converted and upstreamed)\n\nOn the other hand it requires knowledge of a lot of things\n(shell scripting, different operating systems come to mind..)\n\nI like the idea.\n"},{"id":"321552","messageId":"CAGZ79kZn+bjtqBYTWuYqfsKdA=eWreNHQPCLVDGiS_8977VcTA@mail.gmail.com","threadId":"46109","inReplyTo":"CACBZZX5FP_jxXaT+NW8g2JqH89iYajHPjHhxCj=_vWnkxZ=rYQ@mail.gmail.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2017-06-05T19:03:00Z","receivedAt":"2017-06-05T19:03:08Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"> That's never going to be a problem on a less beefy machine with\n> --state=slow,save, since the 30s test is going to be long over by the\n> time the rest of the tests run.\n>\n> Cutting down on these long tail tests allows me to e.g. replace this:\n>\n>     git rebase -i --exec '(make -j56 all && cd t && prove -j56 <some\n> limited glob>)'\n>\n> With a glob that runs the entire test suite, with the rebase only\n> taking marginally longer in most cases while getting much better test\n> coverage than I'd otherwise bother with.\n\nI wonder if this functionality is rather best put into prove?\n\nAlso prove doesn't know which tests are \"interesting\",\ne.g. if you were working on interactive rebase, then you really\nwant the longest test to be run in full?\n\nAnd this \"judge by time, not by interest\" doesn't bode well with\nme.\n\nI have a non-beefy machine such that this particular problem\ndoesn't apply to me, but instead the whole test suite takes just\nlong to run.\n\nFor that I reduce testing intelligently, i.e. I know where I am\nworking on, so I run only some given tests (in case of\nsubmodules I'd go with \"prove t74*\") which would also fix\nyour issue IIUC?\n"},{"id":"321558","messageId":"CACBZZX6CQsJwJDXA_RtQ5YRzcGJnGrO2NoCu7Ys5FWO4dzdhVQ@mail.gmail.com","threadId":"46109","inReplyTo":"CAGZ79kZn+bjtqBYTWuYqfsKdA=eWreNHQPCLVDGiS_8977VcTA@mail.gmail.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2017-06-05T20:37:18Z","receivedAt":"2017-06-05T20:37:47Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"On Mon, Jun 5, 2017 at 9:03 PM, Stefan Beller <sbeller@google.com> wrote:\n>> That's never going to be a problem on a less beefy machine with\n>> --state=slow,save, since the 30s test is going to be long over by the\n>> time the rest of the tests run.\n>>\n>> Cutting down on these long tail tests allows me to e.g. replace this:\n>>\n>>     git rebase -i --exec '(make -j56 all && cd t && prove -j56 <some\n>> limited glob>)'\n>>\n>> With a glob that runs the entire test suite, with the rebase only\n>> taking marginally longer in most cases while getting much better test\n>> coverage than I'd otherwise bother with.\n>\n> I wonder if this functionality is rather best put into prove?\n\nIt would be nice to have a general facility to abort & kill tests\nbased on some criteria as they're run by Test::Harness, but making\nthat work reliably with all the edge cases prove needs to deal with\n(tens/hundreds of thousands of test suites) is a much bigger project\nthan this.\n\n> Also prove doesn't know which tests are \"interesting\",\n> e.g. if you were working on interactive rebase, then you really\n> want the longest test to be run in full?\n\nIf I were hacking rebase or another feature which has such a long\nrunning test then the long running test without the timeout would be\npart of my \"regular\" testing.\n\nThe point of this feature is that most tests aren't like that, then\nyou can use this and do the full test suite every time.\n\n> And this \"judge by time, not by interest\" doesn't bode well with\n> me.\n\nThey're not mutually exclusive.\n\n> I have a non-beefy machine such that this particular problem\n> doesn't apply to me, but instead the whole test suite takes just\n> long to run.\n>\n> For that I reduce testing intelligently, i.e. I know where I am\n> working on, so I run only some given tests (in case of\n> submodules I'd go with \"prove t74*\") which would also fix\n> your issue IIUC?\n\nNo, because even when you're working on e.g. \"grep\" something you're\ndoing occasionally breaks in some completely unrelated test because it\nhappens to cover an aspect of grep which is not part of the main\ntests.\n\nI ran into this recently while hacking the wildmatch() implementation.\nThere's dozens of tests all over the test suite that'll break in\nsubtle ways if wildmatch() breaks, often in cases where the main\nwildmatch test is still passing.\n\nRunning the whole thing, even in a limited timeout fashion, has a much\nhigher chance of catching whatever I've screwed up earlier, before I\ndo an occasional full test suite run. Running the tests in 10 or 15s\nis a much shorter time to wait for during a edit/compile/test cycle.\n"},{"id":"321668","messageId":"20170607102448.bpgxce4kduzxf7a2@sigill.intra.peff.net","threadId":"46109","inReplyTo":"xmqqefuzurj5.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-06-07T10:24:48Z","receivedAt":"2017-06-07T10:24:56Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Jun 05, 2017 at 10:55:42AM +0900, Junio C Hamano wrote:\n\n> I do not expect any single person to tackle the splitting.  I just\n> wished that a patch inspired by this patch (or better yet, a new\n> version of this patch) made the tail end of \"make test\" output to\n> read like this:\n> \n>    ...\n>    [18:32:44] t9400-git-cvsserver-server.sh ...... ok    18331 ms\n>    [18:32:49] t9402-git-cvsserver-refs.sh ........ ok    22902 ms\n>    [18:32:49] t9200-git-cvsexportcommit.sh ....... ok    25163 ms\n>    [18:32:51]\n>    All tests successful.\n>    Files=785, Tests=16928, 122 wallclock secs ( ...\n>    Result: PASS\n> \n>    * The following tests took longer than 15 seconds to run.  We\n>      may want to look into splitting them into smaller files.\n> \n>    t3404-rebase-interactive.sh ...    19 secs\n>    t9001-send-email.sh ...........    22 secs\n>    t9402-git-cvsserver-refs.sh ...    22 secs\n>    t9200-git-cvsexportcommit.sh ..    25 secs\n> \n> when the hidden feature is _not_ used, so that wider set of people\n> will be forced to see that some tests take inordinate amount of\n> time, and entice at least some of them to look into it.\n\nIf you use \"prove\", it already records this information, and it can\nprint it with \"--timer\".\n\nI don't use that myself, though. What's much more interesting (but which\nI haven't found a way to get prove to do out-of-the-box) is to show the\nlongest tests after the fact. I gave a perl snippet to do so in\n\n  http://public-inbox.org/git/20161019205638.m3ytxozzmeh47ml2@sigill.intra.peff.net/\n\nI've actually played with this splitting before, but on my quad-core\n(plus hyperthreading) box, I could never get it to make any improvement\nonce --state=slow was used. The longest test for me is 28s, but the\nwhole suite takes 50s to run. The slow tests get front-loaded, and then\nby the end we have lots of little tests to hand out to each processor\nand they all stay busy.\n\nThe main difference with Ævar's run is that he has a huge number of\nprocessors. So I'm in favor of more splitting, but I also doubt that\neven most Git developers would see any improvement. Or maybe people\nreally do have monstrous boxes. I dunno.\n\nThe biggest changes I've seen in my runs are:\n\n  1. Use \"prove --state=slow,save\"; even with a few processors it makes\n     a big difference.\n\n  2. Point --root at a RAM disk.\n\n  3. I started using Michael's git-test[1], which I have testing each\n     commit on the current branch in the background[2]. That gives me an\n     early warning when there's a failure (I have it play a sad trombone\n     sound, since it's in a minimized terminal), and when I do ask the\n     tests to run, quite often it can answer \"all tests pass\" out of\n     the cache.\n\n-Peff\n\n[1] https://github.com/mhagger/git-test\n\n[2] My hacky script is at https://github.com/peff/git/blob/meta/ci\n"},{"id":"321728","messageId":"3ae7243b-93f9-d7ba-0e3f-d0b3388d57ac@ramsayjones.plus.com","threadId":"46109","inReplyTo":"20170607102448.bpgxce4kduzxf7a2@sigill.intra.peff.net","subject":"Re: [PATCH] test-lib: add ability to cap the runtime of tests","fromName":"Ramsay Jones","fromEmail":"ramsay@ramsayjones.plus.com","sentAt":"2017-06-08T00:59:51Z","receivedAt":"2017-06-08T01:00:01Z","isPatch":true,"sender":{"key":"ramsay@ramsayjones.plus.com","avatar":"https://avatars.githubusercontent.com/u/33702710?v=4"},"body":"\n\nOn 07/06/17 11:24, Jeff King wrote:\n> On Mon, Jun 05, 2017 at 10:55:42AM +0900, Junio C Hamano wrote:\n> \n> If you use \"prove\", it already records this information, and it can\n> print it with \"--timer\".\n\nYes I have\n\n    DEFAULT_TEST_TARGET=prove\n    GIT_PROVE_OPTS='--timer'\n\nin my config.mak and run the test: 'make test >test-out 2>&1'.\n\n> I don't use that myself, though. What's much more interesting (but which\n> I haven't found a way to get prove to do out-of-the-box) is to show the\n> longest tests after the fact.\n\nSo, I have a perl script that can give me that info, like so:\n\nOn Linux, (current master branch), the ten slowest tests:\n\n$ ./test-times.pl -n 10 test-out\n   1   22.269s   t9001-send-email.sh\n   2   15.222s   t7063-status-untracked-cache.sh\n   3   10.965s   t9500-gitweb-standalone-no-errors.sh\n   4    9.978s   t3404-rebase-interactive.sh\n   5    9.270s   t3421-rebase-topology-linear.sh\n   6    8.099s   t0027-auto-crlf.sh\n   7    6.056s   t7112-reset-submodule.sh\n   8    5.937s   t7610-mergetool.sh\n   9    5.711s   t5572-pull-submodule.sh\n  10    5.229s   t6030-bisect-porcelain.sh\n$ \n\n... and those taking 10s or more:\n\n$ ./test-times.pl -t 10 test-out\n   1   22.269s   t9001-send-email.sh\n   2   15.222s   t7063-status-untracked-cache.sh\n   3   10.965s   t9500-gitweb-standalone-no-errors.sh\n$ \n\nHowever, on cygwin (v2.13.0 test output file), the ten slowest:\n\n$ ./test-times.pl -n 10 test-out\n   1  385.057s   t3404-rebase-interactive.sh\n   2  339.694s   t3421-rebase-topology-linear.sh\n   3  224.854s   t7610-mergetool.sh\n   4  211.230s   t6030-bisect-porcelain.sh\n   5  180.297s   t3425-rebase-topology-merges.sh\n   6  179.446s   t3903-stash.sh\n   7  177.600s   t9001-send-email.sh\n   8  175.278s   t5572-pull-submodule.sh\n   9  160.422s   t2013-checkout-submodule.sh\n  10  158.615s   t1013-read-tree-submodule.sh\n$ \n\n... and (some of) those taking 10s or more:\n\n$ ./test-times.pl -t 10 test-out\n   1  385.057s   t3404-rebase-interactive.sh\n   2  339.694s   t3421-rebase-topology-linear.sh\n   3  224.854s   t7610-mergetool.sh\n   4  211.230s   t6030-bisect-porcelain.sh\n\n...\n\n 175   10.389s   t4300-merge-tree.sh\n 176   10.324s   t4213-log-tabexpand.sh\n 177   10.143s   t3034-merge-recursive-rename-options.sh\n 178   10.108s   t1410-reflog.sh\n$ \n\n[On linux a complete run is about 400s and on cygwin about 3hours!]\n\nATB,\nRamsay Jones\n\n"}]}