#Logging & Measuring Performance

#Overview

To this point, we've focused on testing the functional requirements and the correctness of our results. However, there's other criteria: the non-functional requirements or properties of our system that we defined during the requirements gathering phase.

Non-functional requirements are defined as significant, measurable characteristics of a system. They can include things like:

  • Processing speed: how long particular computations or functions take to execute.
  • Volume of data processed: images processed, calculations performed and so on.
  • Network performance: how long transmitting, receiving data over a network takes.
  • Memory consumed: peak, and average memory consumption.
  • Startup time: how long it takes to launch.

Verifying these requirements is only possible if we can collect the appropriate information.

In this section, we'll talk about approaches to measuring and capturing different forms of data. Doing this often involves instrumenting your application -- adding functionality directly to your source code that helps us collect this information. Unlike writing tests, which aim to existing externally to your source code, instrumenting your code can mean making direct modifications.

#Gathering information

The Kotlin and JDK libraries contains a number of useful functions that can help us collect system information.

PackageFunctionPurpose
kotlin.systemexitProcess()Terminate the currently running process.
kotlin.systemgetTimeMillis()Gets system time; subtract two points to get elapsed time in milliseconds.
kotlin.systemmeasureTimeMillis Executes the given block (lambda) and returns elapsed time in milliseconds.
java.langRuntime.getRuntime().freeMemory()Free memory for JVM.
java.langRuntime.getRuntime().totalMemory()Total available memory for JVM.
java.ioFile("/").freeSpaceFree bytes in a directory.

Typically, you want to capture data before and after a critical operation, and then compare them to determine the cost of that operation, whatever that might be (e.g. time that it took to execute, memory consumed).

If you are measuring time, the measureTimeMillis function from the kotlin-stdlib is particularly helpful since it takes a lambda argument which is the block of code to execute.

fun performLengthyComputation() { // a lot of processing goes on here } // manually calculating how long a function takes to run val start = getTimeMillis() performLengthyComputation() val end = getTimeMillis() println("The elapsed time in milliseconds is ${end-start}") // using kotlin-stdlib val elapsed = measureTimeMillis { performLengthyComputation() } println("The elapsed time in milliseconds is $elapsed")

You are going to want to measure everything that you listed in your non-functional requirements.

  • If the functionality that you want to measure spans many classes or functions, you may need to write a top-level function to encapsulate that behaviour so that it's easier to measure.
  • Milliseconds are probably the most coarse-grained you want to measure; there are also functions to measure microseconds but your tests will not be accurate to that level.
  • Keep in mind that your system has other things running that will consume memory, drive space and so on. It is difficult/impossible to completely isolate your application.

To gather information, it's important that you actually use the functions that you want to measure: run the application, and interact with the features that you care about testing. You should plan on doing this multiple times, and collect data from each attempt - average the results to get a more accurate estimate the value that you are collecting, which will reduce the impact of other applications that may be running on the system and consuming resources.

#Logging your data

You will want to gather the information in a text file or database, so that you can examine and analyze it later. You should record each event as a single row in your log file. Each row should contain at least the following:

  • Timestamp: Measure events and record time in milliseconds.
  • Event type: this is more useful if you use logging for debugging purposes (where you can set up INFO, WARNING, EXCEPTION categories of messages). Use a default option here e.g. INFO.
  • Description: Include a description of what you are logging. e.g. "time to execute bigFunction()"
  • Value: Capture the numeric value in question. e.g. time in milliseconds.

Kotlin does not have a built-in logging class, but there are some options:

  • Android has a Log class which is extremely robust and integrates with the development environment.
  • Desktop/JDK users can use the Java Logging API. Although it's a Java library, it is easy to use and compatible with Kotlin.
  • There are also third-party solutions like Log4J that are popular for commercial environments.

Here's an example of using the Java logging class to save log information.

import java.util.logging.* object LoggerExample { private val LOGGER = Logger.getLogger(LoggerExample::class.java.getName()) @JvmStatic fun main(args: Array<String>) { // Set handlers for both console and log file val consoleHandler: Handler? = ConsoleHandler() val fileHandler: Handler? = FileHandler("./example.log") LOGGER.addHandler(consoleHandler) LOGGER.addHandler(fileHandler) // Set to filter what gets logged at each destination consoleHandler?.setLevel(Level.ALL) fileHandler?.setLevel(Level.ALL) LOGGER.level = Level.ALL // Log some data LOGGER.info("Information") LOGGER.config("Configuration") LOGGER.warning("Warning") // Console handler removed LOGGER.removeHandler(consoleHandler) // This should still go to the log file LOGGER.log(Level.FINE, "Finer logged without console") } }

This class was designed for logging large amounts of data, so it provides a great deal of flexibility in determining how data gets saved, and even allows you to send different data to different destinations. By default, this library generates output in XML. Here's one record that was generated from the example above.

<log> <record> <date>2022-03-08T22:13:55.289391Z</date> <millis>1646777635289</millis> <nanos>391000</nanos> <sequence>0</sequence> <logger>LoggerExample</logger> <level>INFO</level> <class>LoggerExample</class> <method>main</method> <thread>1</thread> <message>Information</message> </record> </log>

#Real-time Profiling

Finally, IntelliJ IDEA and Android Studio both include real-time profiling tools that can help you detect performance issues. These are not a replacement for instrumenting your application but are extremely helpful for debugging and finding issues.

To launch the profiler in IntelliJ IDEA:

  • Run - Run
  • Run - Attach Profiler to Process...

This will launch your application. IntelliJ IDEA will collect data from your application as it's running. Once you feel you have enough data (i.e. you've run through the functionality one or more times), choose to stop collecting in the UI, and display the data. You will then be able to browse memory, CPU usage and so on over the time your application was being profiled.

Examining these results is beyond what we will attempt in this course.

Profiling a simple application
Profiling a simple application