Measure current function execution time

Using Swift
1

Hi
I want to measure the execution time for some functions and log it. To do that I wanted to use something like this:

struct MeasureFunc {
    class Internal {
        private let startPoint = Date()
        private let functionName: String

        init(functionName: String) {
            self.functionName = functionName
        }

        deinit {
            NSLog("\(self.functionName): \(Date().timeIntervalSince(startPoint)) seconds")
        }
    }

    private let logPoint: Internal
    init(functionName: String = #function) {
        self.logPoint = Internal(functionName: functionName)
    }
    
#if DEBUG
    @discardableResult
    static func measure(functionName: String = #function) -> Self {
        return Self(functionName: functionName)
    }
#endif
}

and then to use it

func some_func() {
	LogFunctionDuration.measure()
	... rest of the function ...
}

and this should automatically print, when the struct memory is release, would invoke the deinit and print the duration. I need it for debug builds, for now. The outside struct is just to better handle the lifetime of the class.

The problem that I'm having is with the time when deinit is called. In the above example the struct gets deleted on the same line with construction.

If I modify the call to

let v = LogFunctionDuration.measure()
...

then it works fine, but I get warnings for unused variable.

I've tried to use @_transparent for testing to force inline, but same result.

My question would be: how can I extend the lifetime of the struct created into the function measure(), without having more then one line and without having the unused variable warning?
Or can someone recommend another way to measure the current function execution?

Thanks

2

Even the fact that it works with a variable is just a coincidence, it is not guarantee to work. Compiler is allowed to destroy the variable immediately after its last usage, without waiting for the end of the scope.

To have guaranteed lifetime, you need to use withExtendedLifetime(::) - it guarantees that x will not be destroyed until execution of body completes.

But if you need to write

withExtendedLifetime(LogFunctionDuration.measure()) {
    ...
}

you might as well expose your API as this:

loggingDuration {
    ...
}

func loggingDuration<R>(functionName: String = #function, _ body: () throws -> R) rethrows -> R {
    let startPoint = Date()
    defer { NSLog("\(functionName): \(Date().timeIntervalSince(startPoint)) seconds") }
    return try body()
}
3

Hi,

Thanks for the fast response and info. I've thought structs are destroyed just at the end of the scope, like C++ way.

If I understood correctly, with your proposal would mean to wrap all the calls of the measured function withExtendedLifetime or loggingDuration. I wanted to prevent this and have it directly into the function, or part of function, and enable/disable it when needed. The reason is that the same functions are called into lot of places in project.

In the worst case, if there is no nicer one line way, I might use the defer (something like you made in loggingDuration).

Thanks again for the response.

4

If you are using Swift 5.7 or later, consider using a Clock implementation

var clock = ContinuousClock() // Or SuspendingClock 

func logTime(duration: ContinuousClock.Duration, function: String = #function)
{
	print("\(function) Time taken = \(duration)")
}

func doSomething()
{
	let startInstant = clock.now
	defer { logTime(duration: clock.now - startInstant) }

	for i in 0 ..< 1000000
	{
		if (i % 10000 == 0)
		{
			print(i)
		}
	}
}

doSomething() 
// prints "doSomething() Time taken = 0.493060682 seconds" on my Mac in a playground
5

You can also use measure function declared on Clock, which takes a closure in which you wrap your code. IMO this is better than the approach with defer, as the latter is easier to miss when typing out for every measured lines of code.

3 Likes
6

Yes I agree, but the question specifically asks for something that can be put in the function to be measured.

7

I don't think there's anything that prevents the user from putting it in the function to be measured. Expanding on the OP snippet:

func someFunc() {
    let elapsed = ContinuousClock().measure {
      // ... rest of the function ...
    }

    print("\nTime taken by the function invocation: \(elapsed.formatted())")
}
8

ContinuousClock sounds very nice, but I need the code to run on older mac and ios version so I'm not able to use Clock. But thanks for the suggestion, because I've realized Date is not the one to use, so I've found a list of monotonic clocks that should give correct values.

Eventually I'll go with something like

let elapsed = SomeClock.measure { ... }

it is less code and prevents forgetting the defer.

Thanks for all the suggestions and help.

1 Like
9

Except they can't return from the function directly inside the measured block. Not a huge issue, but it seems a bit strange to me to have to set a captured variable to the return value. I think measure should have been designed to return a tuple of the duration and the return type of the closure being measured.

2 Likes
10

You can do this:

func some_func() {
	let startTime = enter(); defer { exit(startTime); }
	... rest of the function ...
}

and the way to not forget "defer" is to simply copy paste that whole line instead of re-typing it.
Beyond that if you do just that "let startTime = enter()" compiler will "remind" you issuing a "startTime is unused" warning, and if you do just "enter()" again compiler would complain about the unused result.

Measuring functions based on closure callbacks have an inherent drawback of forcing a certain code structure (i.e. where before you could use "return" to return from a function you'll need to change the code as return will now return from a closure.

11

I think the best way to model this is with a closure whose result is returned as the result of the measure block. Like so:

import CoreFoundation

@discardableResult
func measure<R>(functionName: String = #function, body: () throws -> R) rethrows -> R {
#if DEBUG // Don't waste time logging unless we're in debug
    // I'm using CoreFoundation's clock as an example,
    // but you can use `clock_gettime(CLOCK_MONOTONIC, ...)` or whatever
    let startTime = CFAbsoluteTimeGetCurrent()
    
    defer {
        let endTime = CFAbsoluteTimeGetCurrent()
        let duration = endTime - startTime
        NSLog("\(functionName): \(duration) seconds")
    }
#endif
    return try body()
}

// example usage:

func someFuncIWantToMeasure() -> Int {
    measure {
        sleep(2)
        return 123 // returns work kind of like normal, even `throw`.
    }
}

Since this wraps the whole lifetime of the body and doesn't escape, there's no need to allocate an object, or even have a struct. Thus, this can just be a free function. All the state is just captured in local variables.

Although there's two things to note here:

  1. If you're in debug, then your measured times are wildly misrepresentation of release builds, unless you have optimizations enabled on your debug builds, which is ... odd.
  2. If you're on Apple's platforms, this is exactly what SignPosts are for. They have a bunch of advantages over this:
    • The data is collected way faster, and can even be gather in release builds, so it's actually useful for drawing conclusions about performance
    • The data is formatted in the Instruments UI, which is much more approachable than a torrent of NSLog messages you need to parse somehow
    • Instruments lets you correlate it with other important information, like dropped frames, CPU usage, slow network IO, page faults, etc.
6 Likes