Problems measuring time

Question
1

I’m repeating this question here from discord because threads on discord are difficult to track.

I’m trying to identify which of my tests is causing my ci/cd pipeline to timeout sometimes. I’ve wrapped diagnostic messages around every test, and after a test finishes, I print out (what I think is) the time taken by the test, and the total time taken so far. Unfortunately, the times don’t add up.
I’m not sure if my calls to the java timing interface are correct. Hoping someone can help.

The code can also be found here scala-rte/src/test/scala/adjuvant/AdjFunSuite.scala at f1dba62e7ff70f58b4239db91d41d1ac07d34634 · jimka2001/scala-rte · GitHub

I’m using scalatest and I’ve created a subclass of AnyFunSuite called AdjFunSuite.
The subclass overrides the test method by calling the given testing function (call by name) but wrapping diagnostics around it.

The individual test is timed by calling System.nanoTime() before and after and computing the subtracted difference. The total time elapsed is computed by calling System.nanoTime() when the AdjFunSuite companion object is initialised, and thereafter calling the elapsed function within that companion object to get the total time since the object was initialized.

The problem is the times don’t add up.


package adjuvant
import adjuvant.Adjuvant.printTime
import org.scalatest.funsuite.AnyFunSuite
class AdjFunSuite extends AnyFunSuite {
  import org.scalactic.source
  import org.scalatest.Tag

  val num_random_tests:Int = sys.env.get("CI_REGISTRY_IMAGE") match {
    case None => 1000   // if interactive
    case Some(_) => 100 // if in ci/cd pipeline
  }

  override def test(testName: String, testTags: Tag*)(testFun: => Any /* Assertion */)(implicit pos: source.Position):Unit = {
    super.test(testName,testTags : _*)(locally{
      import java.time.LocalDateTime

      val start = System.nanoTime()
      println("[ starting " + testName + " at " + LocalDateTime.now())
      var finished = false
      try{
        testFun // <<<<<------ run the code from the user's test
        finished = true
      }
      finally{
        val end = System.nanoTime()
        if (finished)
          println("] finished " + testName + ": " + printTime(end-start) + " total time: " + printTime(AdjFunSuite.elapsed()))
        else
          println("] aborted " + testName + ": " + printTime(end - start))
      }
    })(pos)
  }
}

object AdjFunSuite {
  val testsStarted:Long = System.nanoTime()

  def elapsed():Long = System.nanoTime() - testsStarted
}

Here is some sample output which I get in the ci/cd pipeline log file.

[ starting canonicalize at 2024-11-11T13:38:17.853326 total time: 11 sec 697 ms
] finished canonicalize at : 2024-11-11T13:38:17.858771 test time: 5 us total time: 11 sec 697 ms
[ starting Thompson/brz/Trait3 at 2024-11-11T13:38:17.859171 total time: 11 sec 697 ms
] finished Thompson/brz/Trait3 at : 2024-11-11T13:38:17.863654 test time: 4 us total time: 11 sec 697 ms
[ starting discovered 463 at 2024-11-11T13:38:17.864058 total time: 11 sec 697 ms
] finished discovered 463 at : 2024-11-11T13:38:17.929005 test time: 64 us total time: 11 sec 698 ms
[ starting discovered 463 b at 2024-11-11T13:38:17.929656 total time: 11 sec 698 ms
] finished discovered 463 b at : 2024-11-11T13:38:48.388613 test time: 30 ms total time: 12 sec 728 ms
[ starting discovered 479 at 2024-11-11T13:38:48.390377 total time: 12 sec 728 ms
] finished discovered 479 at : 2024-11-11T13:38:48.391525 test time: 1 us total time: 12 sec 728 ms

We see it starts at 13:38:17 and ends at 13:38:48 but claims only 12 seconds have elapsed.
am I interpreting the data wrong?

2

My tests are declared shown in this file.

basically like this:


class ExtractTestSuite  extends AdjFunSuite {
  ...

  test("extraction 31"){
    // make some assertions
    assert(this and that ...)
  }
...
}
3

Is it possible there’s a bug in adjuvant.Adjuvant.printTime?

4

Also, this seems suspicious:

object AdjFunSuite {
val testsStarted:Long = System.nanoTime()

def elapsed():Long = System.nanoTime() - testsStarted
}

perhaps the AdjFunSuite companion object is getting initialized at a different time than you expect?

Offhand, this looks to me like a logic error in your code rather than something like a misunderstanding about what nanoTime does.

5

I can write some tests for this function to see if it is really correct.

  def printTime(time: Long): String = {
    def recur(time: Long, divisors: List[Int]): List[Int] = {
      divisors match {
        case Nil => Nil
        case d :: ds => (time / d).toInt :: recur(time / d, ds)
      }
    }

    val List(ns, us, ms, sec, min, hour) = recur(time, List(1000, 1000, 1000,
                                                            60, 60, 60))
    if (hour > 0)
      s"$hour hours $min min $sec sec"
    else if (min > 0)
      s"$min min $sec sec"
    else if (sec > 0)
      s"$sec sec $ms ms"
    else if (ms > 0)
      s"$ms ms"
    else if (us > 0)
      s"$us us"
    else
      s"$ns ns"
  }
6

with regard to the companion object. How many times will testsStarted get initialized? Once per run, or multiple times?

I could put a print in there to verify that it is only being initialized once.

7

That’s the sort of debugging I suggest you do.

1 Like
8

Stdlib classes such as java.time.Duration could be helpful here.

9

Thanks for the suggestion @SethTisue!

Voila, there were a couple of bugs in printTime.
one bug was I need to change
(time / d).toInt :: recur(time / d, ds) to
(time % d).toInt :: recur(time / d, ds).

Second error is that I’m getting Int overflow. I need to do computation with Long not with Int.


  def printTime(time: Long): String = {
    def recur(time: Long, divisors: List[Long]): List[Long] = {
      divisors match {
        case Nil => Nil
        case d :: ds => (time % d).toInt :: recur(time / d, ds)
      }
    }

    val List(ns, us, ms, sec, min, hour) = recur(time, List(1000L, 1000L, 1000L,
                                                            60L, 60L, 60L))
    if (hour > 0)
      s"$hour hours $min min $sec sec"
    else if (min > 0)
      s"$min min $sec sec"
    else if (sec > 0)
      s"$sec sec $ms ms"
    else if (ms > 0)
      s"$ms ms"
    else if (us > 0)
      s"$us us"
    else
      s"$ns ns"
  }
1 Like
10

Output looks much better now.

[ starting sort 2 at 2024-11-12T11:07:46.648217 total time: 4 min 54 sec
] finished sort 2 at : 2024-11-12T11:07:46.652183 test time: 3 ms total time: 4 min 54 sec
[ starting triangle inequality at 2024-11-12T11:07:46.652577 total time: 4 min 54 sec
] finished triangle inequality at : 2024-11-12T11:07:47.147917 test time: 495 ms total time: 4 min 54 sec
[ starting mdtd at 2024-11-12T11:07:47.148907 total time: 4 min 54 sec
] finished mdtd at : 2024-11-12T11:07:47.152049 test time: 3 ms total time: 4 min 54 sec
[ starting typeEquivalent random at 2024-11-12T11:07:47.152623 total time: 4 min 54 sec
] finished typeEquivalent random at : 2024-11-12T11:07:55.683030 test time: 8 sec 530 ms total time: 5 min 3 sec
[ starting typeEquivalent fixed at 2024-11-12T11:07:55.683765 total time: 5 min 3 sec
] finished typeEquivalent fixed at : 2024-11-12T11:07:55.685766 test time: 2 ms total time: 5 min 3 sec
[ starting test 103 at 2024-11-12T11:07:55.686148 total time: 5 min 3 sec
] finished test 103 at : 2024-11-12T11:07:55.686782 test time: 634 us total time: 5 min 3 sec
[ starting genus implicits at 2024-11-12T11:07:55.687154 total time: 5 min 3 sec
] finished genus implicits at : 2024-11-12T11:07:55.687207 test time: 55 us total time: 5 min 3 sec
1 Like
11

Sweet!