Runtimes for Nim code are absurdly long

[shirleyquirk]

Describe the bug The runtime for Nim code cannot be accurate. Take for example 'Cat years, Dog years', one of the simplest possible kata. When running a solution the tests report: Completed in 0.0031ms for the standard tests and Completed in 0.0186ms for the random tests

meanwhile the total reported time is 4162ms !!

This obviously has very real effects on more complicated tests, making some of them impossible to run under 12s

To Reproduce

Run 'Cat years, Dog years' with any of the solutions, e.g.

proc toYears*(humanYears: int): tuple[humanYears, catYears, dogYears: int] =
  result = (
    humanYears,
    15+int(humanYears>1)*9+int(humanYears>2)*(humanYears-2)*4,
    15+int(humanYears>1)*9+int(humanYears>2)*(humanYears-2)*5
  )

Expected behavior Total time should be less than 1ms.

Screenshots

Browser If applicable, please provide your browser information.

• OS: Windows 10
• Browser: Edge
• Version: Version 103.0.1264.49 (Official build) (64-bit)

Additional context

I can see that code is being compiled with -d:release, so that's not the issue, at least.

The runtime seems proportional to the number of tests written in code, but not the number of tests run

e.g.

for i in 0..200:
  test "random test " & $i:
    for j in 0..100:
      let h = rand(25) + 1
      check toYears(h) == sol(h)

gives a runtime of 6698ms for 200 tests run

while this (which basically copy pastes the test 17 times)

import macros
macro multiples(x:untyped):untyped =
  result = nnkStmtList.newNimNode()
  for i in 0..16:
    result.add x

multiples:
  test "Random Test":
    for i in 0..100:
      let h = rand(25) + 1
      check toYears(h) == sol(h)

sometimes times out, or gives a runtime of just under 12s

[hobovsky]

It's normal for some languages, for example Scala:

JVM-based languages like Scala, Kotlin, Clojure(?), seem to have 6-7s of additional startup overhead.

Total time reported includes time for spinning up a container, compilation of source code, starting test framework and discovery of test suites and test cases. Depending on how tests are written, additional discrepancies can come from time spent on generation of random inputs and running reference solution.

Generally, though, it should not be as much of an issue as it might seem for you. It could make it harder to create performance kata which require stricter control of execution times, and where 3s fluctuations from test run to test run can have significant impact. But for most of kata, it's enough to get ~100 tests run below time limit imposed by the runner, no matter if it takes 1 second for JS, 3 seconds for C++, or 9 seconds for Scala. Nim's container timeout seems to be set to 12 seconds (see here), so maybe it would be enough to ask and have it increased to 16 seconds?

[shirleyquirk]

Thank you for your quick reply,

I understand from the perspective of hosting the code that you have to limit the total time running a kata takes, including compilation time. I should point out that Nim is not an interpreted language, so there is no startup overhead, but it does compile slower than C.

I don't understand why

test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true
test "foo": check true

times out.

perhaps i can try something other than unittest to cut down on compile times, and increasing the container timeout sounds like a great idea as well. where would i be able to make that request, do you know?

[hobovsky]

This repository and this thread is a good place, your issue can stay here and probably will be processed by admins soon.

[error256]

So there seem to be 2 things: a constant latency and slow compilation of testing code. Both seem to be consistent between Codewars and https://nim.godbolt.org/, so I'm assuming the reasons probably are the same. An empty file without tests takes 4-4.7 seconds on CW. What is this time, recompiling parts of the standard library? In Compiler Explorer, I see

CC: stdlib_digitsutils.nim
CC: stdlib_assertions.nim
CC: stdlib_dollars.nim
CC: stdlib_system.nim
CC: example.nim

for an empty file. I don't know, is it possible to save precompiled modules? 5 times test "foo": check true is 2698 lines, while 10 times that is 4879 lines. It looks like templated test and check are inlined everywhere? Tests without many copies of test seem to work OK (just an example; the reference solution usually shouldn't be called for fixed tests):

import random, strformat

iterator testCases(): int {.closure.} =
  for each in [1, 2, 3, 4, 5, 6, 7, 8, 9, 10]:
    yield each
  randomize()
  for i in 1..100:
    yield rand(1000)

proc mul123RefImpl(x: int): int = x * 123

for x in testCases():
  test &"mul123({x})":
    let actual = mul123(x)
    let expected = mul123RefImpl(x)
    check(actual == expected)

[kazk]

We can increase the timeout if there's nothing we can do. But let's try to figure out what's causing this first, and find any fix/workaround.

I don't know, is it possible to save precompiled modules?

It should be, or it was possible before at least. We've been testing once while building the container image to generate nimcache in ~/.cache/nim/ to avoid recompiling standard libraries on each submission. I just noticed --trmacros:off flag used in the actual submissions (added to prevent easy cheating) is missing there, so maybe that's why? It was also missing for Nim 1.0 image, though.

Is there a better way to precompile everything up front? The example test used is minimal, so perhaps only parts of the standard library is precompiled.

[kazk]

Compiler flags used:

nim compile \
  --run \
  --define:release \
  --warnings:on \
  --hints:off \
  --verbosity:0 \
  --stackTrace:on \
  --lineTrace:on \
  --checks:on \
  --trmacros:off \
  tests.nim

[kazk]

An empty file without tests takes 4-4.7 seconds on CW. What is this time, recompiling parts of the standard library?

During the image build, a minimal example is compiled to generate some nimcache for parts of standard library and test reporter.

solution.nim

```nim proc add*(x, y: int): int = x + y ```

solution_test.nim

```nim suite "add": test "1 + 1 = 2": check(add(1, 1) == 2) ```

tests.nim

```nim import unittest, codewars_output addOutputFormatter(OutputFormatter(newCodewarsOutputFormatter())) import solution except test, suite, check # Disallow solution from overriding unittest's identifiers include solution_tests ```

The verbose output shows:

CC: stdlib_digitsutils.nim
CC: stdlib_assertions.nim
CC: stdlib_dollars.nim
CC: stdlib_io.nim
CC: stdlib_system.nim
CC: stdlib_exitprocs.nim
CC: stdlib_parseutils.nim
CC: stdlib_math.nim
CC: stdlib_algorithm.nim
CC: stdlib_unicode.nim
CC: stdlib_strutils.nim
CC: stdlib_streams.nim
CC: stdlib_options.nim
CC: stdlib_times.nim
CC: stdlib_hashes.nim
CC: stdlib_sets.nim
CC: stdlib_os.nim
CC: stdlib_strformat.nim
CC: stdlib_terminal.nim
CC: stdlib_unittest.nim
CC: stdlib_pcre.nim
CC: stdlib_tables.nim
CC: stdlib_util.nim
CC: stdlib_nre.nim
CC: ../home/codewarrior/.nimble/pkgs/codewars_output-0.1.0/codewars_output.nim
CC: solution.nim
CC: tests.nim

Testing with empty solution and tests with Nim 1.6 shows:

CC: stdlib_digitsutils.nim
CC: stdlib_assertions.nim
CC: stdlib_dollars.nim
CC: stdlib_io.nim
CC: stdlib_system.nim
CC: stdlib_exitprocs.nim
CC: stdlib_parseutils.nim
CC: stdlib_math.nim
CC: stdlib_algorithm.nim
CC: stdlib_strutils.nim
CC: stdlib_streams.nim
CC: stdlib_options.nim
CC: stdlib_os.nim
CC: stdlib_terminal.nim
CC: stdlib_unittest.nim
CC: tests.nim

With Nim 1.0:

CC: stdlib_assertions.nim
CC: stdlib_io.nim
CC: stdlib_system.nim
CC: stdlib_strutils.nim
CC: stdlib_sets.nim
CC: stdlib_os.nim
CC: stdlib_terminal.nim
CC: stdlib_unittest.nim
CC: tests.nim

[kazk]

a constant latency

Nim 1.6 seems slightly slower than 1.0. ~4-5s vs ~6s for empty tests.

Nim 1.6 is recompiling more modules from the standard library for some reason, but the difference is not that significant.

slow compilation of testing code

Nim 1.6 can take more than twice as long to compile when the number of test in tests is high. Workaround is to avoid having too many test like @error256 wrote above.

[shirleyquirk]

timing nim's code generation separately from the c compiler pass for a trivial test (test "foo": check true 50 times) shows that most of the time is spent during c compilation.

passing --cc:clang (using clang instead of gcc) reduces that time dramatically. (for me: gcc takes 13 seconds and clang 7 )

reducing the number of tests might be challenging for e.g. Esolang #3 Custom Paintfuck Interpreter which has 31 tests

refactoring the tests to minimize the number of test instantiations does help, by doing this i was able to get that kata to compile in 5s with nim1.0 and 9s with 1.6. it's a pain, though. maybe with some work it could be automated by writing new test or suite templates idk.

could you please add --cc:clang to the compiler flags and see if that helps?

[kazk]

For 50 test "foo": check true, --cc:clang does help. ~11s vs ~7s on my laptop.

I still think the number of test should be reduced anyway, but we can start using --cc:clang.

[kazk]

Switched to Clang

[shirleyquirk]

Thank you! Esolang #3 now works without any refactoring. Yes, number of tests should be reduced as well, but for now this is a great improvement.