From 14ca111f33eebb2c8394a225f9ed9cc712f3bcae Mon Sep 17 00:00:00 2001 From: zeripath Date: Tue, 2 Jun 2020 02:39:44 +0100 Subject: [PATCH] log slow tests (#11487) * log slow tests Signed-off-by: Andrew Thornton * placate lint Signed-off-by: Andrew Thornton * More lint placation Co-authored-by: 6543 <6543@obermui.de> Co-authored-by: 6543 <6543@obermui.de> Co-authored-by: techknowlogick --- integrations/README.md | 22 ++++++++++++++++++++++ integrations/integration_test.go | 22 ++++++++++++++++++++++ integrations/testlogger.go | 32 +++++++++++++++++++++++++++++++- 3 files changed, 75 insertions(+), 1 deletion(-) diff --git a/integrations/README.md b/integrations/README.md index fccce2ec65..ccb55377f5 100644 --- a/integrations/README.md +++ b/integrations/README.md @@ -70,3 +70,25 @@ For other databases(replace MSSQL to MYSQL, MYSQL8, PGSQL): ``` TEST_MSSQL_HOST=localhost:1433 TEST_MSSQL_DBNAME=test TEST_MSSQL_USERNAME=sa TEST_MSSQL_PASSWORD=MwantsaSecurePassword1 make test-mssql#GPG ``` + +## Setting timeouts for declaring long-tests and long-flushes + +We appreciate that some testing machines may not be very powerful and +the default timeouts for declaring a slow test or a slow clean-up flush +may not be appropriate. + +You can either: + +* Within the test ini file set the following section: + +```ini +[integration-tests] +SLOW_TEST = 10s ; 10s is the default value +SLOW_FLUSH = 5S ; 5s is the default value +``` + +* Set the following environment variables: + +```bash +GITEA_SLOW_TEST_TIME="10s" GITEA_SLOW_FLUSH_TIME="5s" make test-sqlite +``` diff --git a/integrations/integration_test.go b/integrations/integration_test.go index 3c0125af6c..0d49e524d5 100644 --- a/integrations/integration_test.go +++ b/integrations/integration_test.go @@ -22,6 +22,7 @@ import ( "runtime" "strings" "testing" + "time" "code.gitea.io/gitea/models" "code.gitea.io/gitea/modules/base" @@ -66,6 +67,27 @@ func TestMain(m *testing.M) { mac = routes.NewMacaron() routes.RegisterRoutes(mac) + // integration test settings... + if setting.Cfg != nil { + testingCfg := setting.Cfg.Section("integration-tests") + slowTest = testingCfg.Key("SLOW_TEST").MustDuration(slowTest) + slowFlush = testingCfg.Key("SLOW_FLUSH").MustDuration(slowFlush) + } + + if os.Getenv("GITEA_SLOW_TEST_TIME") != "" { + duration, err := time.ParseDuration(os.Getenv("GITEA_SLOW_TEST_TIME")) + if err == nil { + slowTest = duration + } + } + + if os.Getenv("GITEA_SLOW_FLUSH_TIME") != "" { + duration, err := time.ParseDuration(os.Getenv("GITEA_SLOW_FLUSH_TIME")) + if err == nil { + slowFlush = duration + } + } + var helper testfixtures.Helper if setting.Database.UseMySQL { helper = &testfixtures.MySQL{} diff --git a/integrations/testlogger.go b/integrations/testlogger.go index eed0bf788d..9636c4892e 100644 --- a/integrations/testlogger.go +++ b/integrations/testlogger.go @@ -13,12 +13,17 @@ import ( "strings" "sync" "testing" + "time" "code.gitea.io/gitea/modules/log" "code.gitea.io/gitea/modules/queue" ) -var prefix string +var ( + prefix string + slowTest = 10 * time.Second + slowFlush = 5 * time.Second +) // TestLogger is a logger which will write to the testing log type TestLogger struct { @@ -87,6 +92,7 @@ func (w *testLoggerWriterCloser) Close() error { // PrintCurrentTest prints the current test to os.Stdout func PrintCurrentTest(t testing.TB, skip ...int) func() { + start := time.Now() actualSkip := 1 if len(skip) > 0 { actualSkip = skip[0] @@ -100,9 +106,33 @@ func PrintCurrentTest(t testing.TB, skip ...int) func() { } writerCloser.setT(&t) return func() { + took := time.Since(start) + if took > slowTest { + if log.CanColorStdout { + fmt.Fprintf(os.Stdout, "+++ %s is a slow test (took %v)\n", fmt.Formatter(log.NewColoredValue(t.Name(), log.Bold, log.FgYellow)), fmt.Formatter(log.NewColoredValue(took, log.Bold, log.FgYellow))) + } else { + fmt.Fprintf(os.Stdout, "+++ %s is a slow tets (took %v)\n", t.Name(), took) + } + } + timer := time.AfterFunc(slowFlush, func() { + if log.CanColorStdout { + fmt.Fprintf(os.Stdout, "+++ %s ... still flushing after %v ...\n", fmt.Formatter(log.NewColoredValue(t.Name(), log.Bold, log.FgRed)), slowFlush) + } else { + fmt.Fprintf(os.Stdout, "+++ %s ... still flushing after %v ...\n", t.Name(), slowFlush) + } + }) if err := queue.GetManager().FlushAll(context.Background(), -1); err != nil { t.Errorf("Flushing queues failed with error %v", err) } + timer.Stop() + flushTook := time.Since(start) - took + if flushTook > slowFlush { + if log.CanColorStdout { + fmt.Fprintf(os.Stdout, "+++ %s had a slow clean-up flush (took %v)\n", fmt.Formatter(log.NewColoredValue(t.Name(), log.Bold, log.FgRed)), fmt.Formatter(log.NewColoredValue(flushTook, log.Bold, log.FgRed))) + } else { + fmt.Fprintf(os.Stdout, "+++ %s had a slow clean-up flush (took %v)\n", t.Name(), flushTook) + } + } _ = writerCloser.Close() } }