Invalid test running duration in test panel

[haashem]

Look into these tests duration, you notice it says each tests took 2.3 seconds. so each test group duration is about 7 seconds. and the whole test took 14 seconds. which is not right! in real all of it takes less than 1 second.

is there any mistakes in calculating tests duration?
I also suggest to display test count, test group and test file duration like this:

[DanTup]

Could you capture a log for a run where the wrong durations are shown?

• Run Dart: Capture Logs
• Untick Analysis Server, but keep everything else ticked
• Run the tests
• Click Cancel on the logging dialog to stop the log and open it
• Provide the log and a screenshot of what was shown for that run

I also suggest to display test count, test group and test file duration like this:

That seems reasonable - please file a separate issue for it so it isn't lost when this bug is fixed.

Thanks!

[haashem]

!! PLEASE REVIEW THIS LOG FOR SENSITIVE INFORMATION BEFORE SHARING !!

Dart Code extension: 3.12.1
Flutter extension: 3.12.1 (activated)

App: Visual Studio Code
Version: 1.46.1
Platform: mac

Workspace type: Flutter
Multi-root?: false

Dart SDK:
    Loc: /Users/hashem/Desktop/Xcode_Projects/flutter/bin/cache/dart-sdk
    Ver: 2.8.2
Flutter SDK:
    Loc: /Users/hashem/Desktop/Xcode_Projects/flutter
    Ver: 1.17.1

HTTP_PROXY: undefined
NO_PROXY: undefined

Wed Jul 08 2020 [18:27:11 GMT+0430 (Iran Daylight Time)] Log file started
[6:27:15 PM] [General] [Info] Starting debug session...
[6:27:15 PM] [General] [Info]     workspace: /Users/hashem/Desktop/Xcode_Projects/Flutter Apps/number_trivia clean architecture
[6:27:15 PM] [General] [Info]     program  : /Users/hashem/Desktop/Xcode_Projects/Flutter Apps/number_trivia clean architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart
[6:27:15 PM] [General] [Info] Using workspace as cwd: /Users/hashem/Desktop/Xcode_Projects/Flutter Apps/number_trivia clean architecture
[6:27:15 PM] [General] [Info] Detected launch project as Flutter
[6:27:15 PM] [General] [Info] Detected launch project as a Test project
[6:27:15 PM] [General] [Info] Using FlutterTest debug adapter for this session
[6:27:15 PM] [General] [Info] Checking for errors before launching
[6:27:15 PM] [General] [Info] Spawning a new flutterTest debugger
[6:27:15 PM] [General] [Info] Debug session starting...
    {
        "name": "Dart ",
        "noDebug": true,
        "request": "launch",
        "type": "dart",
        "program": "/Users/hashem/Desktop/Xcode_Projects/Flutter Apps/number_trivia clean architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart",
        "cwd": "/Users/hashem/Desktop/Xcode_Projects/Flutter Apps/number_trivia clean architecture",
        "dartVersion": "2.8.2",
        "toolEnv": {
            "FLUTTER_HOST": "VSCode",
            "PUB_ENVIRONMENT": "vscode.dart-code"
        },
        "sendLogsToClient": true,
        "globalFlutterArgs": [],
        "args": [],
        "vmAdditionalArgs": [],
        "vmServicePort": 0,
        "dartPath": "/Users/hashem/Desktop/Xcode_Projects/flutter/bin/cache/dart-sdk/bin/dart",
        "maxLogLineLength": 2000,
        "pubPath": "/Users/hashem/Desktop/Xcode_Projects/flutter/bin/cache/dart-sdk/bin/pub",
        "pubSnapshotPath": "/Users/hashem/Desktop/Xcode_Projects/flutter/bin/cache/dart-sdk/bin/snapshots/pub.dart.snapshot",
        "debugSdkLibraries": false,
        "debugExternalLibraries": false,
        "showDartDeveloperLogs": true,
        "useFlutterStructuredErrors": true,
        "evaluateGettersInDebugViews": true,
        "evaluateToStringInDebugViews": true,
        "flutterVersion": "1.17.1",
        "forceFlutterVerboseMode": true,
        "flutterTrackWidgetCreation": true,
        "flutterMode": "debug",
        "flutterPlatform": "default",
        "flutterPath": "/Users/hashem/Desktop/Xcode_Projects/flutter/bin/flutter",
        "deviceId": "FD3E925D-E92C-4B32-9EDB-7512A3AC521F",
        "deviceName": "iPhone 11 Pro Max (ios)",
        "showMemoryUsage": false,
        "debugServer": 58042,
        "debuggerType": 3
    }
[6:27:15 PM] [General] [Warn] Did not find session 485a71f4-849c-4734-9357-2751432b0d01 to handle dart.progressStart. There were 0 sessions:
[6:27:15 PM] [General] [Warn] Event will be queued and processed when the session start event fires
[6:27:15 PM] [General] [Info] Processing delayed event dart.progressStart for session 485a71f4-849c-4734-9357-2751432b0d01
[6:27:15 PM] [FlutterTest] [Info] [Dart ] Spawning /Users/hashem/Desktop/Xcode_Projects/flutter/bin/flutter with args ["test","--machine","test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"]
[6:27:15 PM] [FlutterTest] [Info] [Dart ] ..  in /Users/hashem/Desktop/Xcode_Projects/Flutter Apps/number_trivia clean architecture
[6:27:15 PM] [FlutterTest] [Info] [Dart ] ..  with {"toolEnv":{"FLUTTER_HOST":"VSCode","PUB_ENVIRONMENT":"vscode.dart-code"}}
[6:27:15 PM] [FlutterTest] [Info] [Dart ]     PID: 26005
[6:27:17 PM] [FlutterTest] [Info] [Dart ] <== {"protocolVersion":"0.1.1","runnerVersion":null,"pid":26169,"type":"start","time":0}
[6:27:17 PM] [FlutterTest] [Info] [Dart ] <== {"suite":{"id":0,"platform":"vm","path":"/Users/hashem/Desktop/Xcode_Projects/Flutter Apps/number_trivia clean architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"suite","time":1}
[6:27:17 PM] [FlutterTest] [Info] [Dart ] <== {"test":{"id":1,"name":"loading /Users/hashem/Desktop/Xcode_Projects/Flutter Apps/number_trivia clean architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart","suiteID":0,"groupIDs":[],"metadata":{"skip":false,"skipReason":null},"line":null,"column":null,"url":null},"type":"testStart","time":3}
[6:27:17 PM] [FlutterTest] [Info] [Dart ] <== {"count":1,"type":"allSuites","time":7}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"testID":1,"result":"success","skipped":false,"hidden":true,"type":"testDone","time":2892}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"group":{"id":2,"suiteID":0,"parentID":null,"name":null,"metadata":{"skip":false,"skipReason":null},"testCount":6,"line":null,"column":null,"url":null},"type":"group","time":2897}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"group":{"id":3,"suiteID":0,"parentID":2,"name":"getConcreteNumberTrivia","metadata":{"skip":false,"skipReason":null},"testCount":3,"line":34,"column":3,"url":"file:///Users/hashem/Desktop/Xcode_Projects/Flutter%20Apps/number_trivia%20clean%20architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"group","time":2898}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"test":{"id":4,"name":"getConcreteNumberTrivia should perfrom a GET request on a URL with number being endpoint and with application/json header","suiteID":0,"groupIDs":[2,3],"metadata":{"skip":false,"skipReason":null},"line":38,"column":5,"url":"file:///Users/hashem/Desktop/Xcode_Projects/Flutter%20Apps/number_trivia%20clean%20architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"testStart","time":2898}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"testID":4,"result":"success","skipped":false,"hidden":false,"type":"testDone","time":2945}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"test":{"id":5,"name":"getConcreteNumberTrivia should return NumberTriviaModel when the response code is 200 (success)","suiteID":0,"groupIDs":[2,3],"metadata":{"skip":false,"skipReason":null},"line":52,"column":5,"url":"file:///Users/hashem/Desktop/Xcode_Projects/Flutter%20Apps/number_trivia%20clean%20architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"testStart","time":2945}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"testID":5,"result":"success","skipped":false,"hidden":false,"type":"testDone","time":2955}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"test":{"id":6,"name":"getConcreteNumberTrivia should throw a ServerException when the response code is not 200","suiteID":0,"groupIDs":[2,3],"metadata":{"skip":false,"skipReason":null},"line":65,"column":5,"url":"file:///Users/hashem/Desktop/Xcode_Projects/Flutter%20Apps/number_trivia%20clean%20architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"testStart","time":2955}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"testID":6,"result":"success","skipped":false,"hidden":false,"type":"testDone","time":2963}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"group":{"id":7,"suiteID":0,"parentID":2,"name":"getRandomNumberTrivia","metadata":{"skip":false,"skipReason":null},"testCount":3,"line":77,"column":3,"url":"file:///Users/hashem/Desktop/Xcode_Projects/Flutter%20Apps/number_trivia%20clean%20architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"group","time":2964}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"test":{"id":8,"name":"getRandomNumberTrivia should perfrom a GET request on a URL with random being endpoint and with application/json header","suiteID":0,"groupIDs":[2,7],"metadata":{"skip":false,"skipReason":null},"line":80,"column":5,"url":"file:///Users/hashem/Desktop/Xcode_Projects/Flutter%20Apps/number_trivia%20clean%20architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"testStart","time":2964}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"testID":8,"result":"success","skipped":false,"hidden":false,"type":"testDone","time":2970}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"test":{"id":9,"name":"getRandomNumberTrivia should return NumberTriviaModel when the response code is 200 (success)","suiteID":0,"groupIDs":[2,7],"metadata":{"skip":false,"skipReason":null},"line":94,"column":5,"url":"file:///Users/hashem/Desktop/Xcode_Projects/Flutter%20Apps/number_trivia%20clean%20architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"testStart","time":2970}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"testID":9,"result":"success","skipped":false,"hidden":false,"type":"testDone","time":2976}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"test":{"id":10,"name":"getRandomNumberTrivia should throw a ServerException when the response code is not 200","suiteID":0,"groupIDs":[2,7],"metadata":{"skip":false,"skipReason":null},"line":107,"column":5,"url":"file:///Users/hashem/Desktop/Xcode_Projects/Flutter%20Apps/number_trivia%20clean%20architecture/test/features/number_trivia/data/datasources/number_trivia_remote_data_source_test.dart"},"type":"testStart","time":2976}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"testID":10,"result":"success","skipped":false,"hidden":false,"type":"testDone","time":2980}
[6:27:20 PM] [FlutterTest] [Info] [Dart ] <== {"success":true,"type":"done","time":3009}
[6:27:21 PM] [FlutterTest] [Info] [Dart ] Process terminated! 0, null
[6:27:21 PM] [VmService] [Info] [Dart ] Process exited (0)
[6:27:21 PM] [VmService] [Info] [Dart ] Disconnect requested!
[6:27:21 PM] [VmService] [Info] [Dart ] TERM: Requested to terminate with SIGINT...
[6:27:21 PM] [VmService] [Info] [Dart ] TERM: Did not need to terminate processes
[6:27:21 PM] [VmService] [Info] [Dart ] TERM: Removing all stored data...
[6:27:21 PM] [VmService] [Info] [Dart ] TERM: Waiting for process to finish...
[6:27:21 PM] [VmService] [Info] [Dart ] TERM: Disconnecting...
[6:27:21 PM] [General] [Info] Debugger:SessionDuration timing: 5398ms (FlutterTest)
Wed Jul 08 2020 [18:27:30 GMT+0430 (Iran Daylight Time)] Log file ended

[DanTup]

Oh, I see - the time provided by the test runner is actually "time since the test run started" rather than "time of this test" 😱

Thanks for noticing! 😁