get_time_ns on iOS is 'slow'

[gutley]

Hi,

get_time_ns is too slow on iOS nowadays (and probably macOS) and can account for a substantial amount of CPU usage in the worker thread just to check it, especially when IOTHUB_CLIENT_CORE_INSTANCE.do_work_freq_ms is its default value of 1

Since macOS 10.12 and iOS 10, clock_gettime is available for use with CLOCK_MONOTONIC and so get_time_ns should be updated to reflect this.

I don't have enough other platforms to do a fully testable Pull Request. In my local copy I just add this at the start of get_time_ns:

int get_time_ns(struct timespec* ts)
{
    int err;

    if (__builtin_available(iOS 10.0, *))
    {
        err = clock_gettime(CLOCK_MONOTONIC, ts);
        return err;
    }

#ifdef __MACH__
....

Doing so makes CPU usage of get_time_ns virtually negligible

[gutley]

To further demonstrate the issue, here is a 20 seconds sample of my app sitting doing nothing with a default IOTHUB_CLIENT_CORE_INSTANCE.do_work_freq_ms and the current implementation of get_time_ns.

As you can see, get_time_ns accounts for about 2.5 seconds of the 3.5 seconds _LL_DoWork spends just spinning its heals.

[danewalton]

This might be asking a lot but more for my education and I'm curious....can you do the profiling for the implementation you're asking for? For comparison?

[gutley]

Sorry for the delay. Here it is with my change:

So about 57ms instead of 2.5 secs.

A further optimisation would be to remove the if (__builtin_available(iOS 10.0, *)) test if the minimum build target for the library is >= iOS 10

[danewalton]

Ahh great to know yea that's significant. I'm looking into the best way to get the quicker version in but only have it compile on the systems that support it. Examples which have this kind of change which either had issues or worked.

Redis: https://github.com/redis/redis/pull/7644/files#diff-4bbdf3e8cafcbb3340a2eaecf977a215b5f4886638cd6b031a570ca219fa571bR143-R170

Reverted on nodeJS: https://github.com/nodejs/node/issues/11104

I'll keep digging thanks for the info.

[danewalton]

Hey @gutley are you able to try the PR started here: https://github.com/Azure/azure-c-shared-utility/pull/559

monotomic time looks to be failing in the implementation's ut but realtime looks to work.

[gutley]

@danewalton Excuse my ignorance, but what does 'ut' mean in ' the implementations ut'

Yes i can test but am on vacation for a few days, so not for a week or so.

[danewalton]

Ah sorry about that bad habit with the acronyms. Unit tests. The tests for Condition_UT were failing for thread conditions using the monotonic option but not the real.

[danewalton]

Alright just for my own knowledge I tried profiling my iOS app myself and using the old version I'm getting numbers that aren't so bad. Could you share the conditions of your build and profiling?

[danewalton]

Hi @gutley any updates here? I'm not seeing the same performance degradation.

[gutley]

@danewalton Sorry, no updates. Been busy with other stuff so not had time to get back on this. Hopefully in a week or two.

[gutley]

@danewalton - Dane - As you may have noticed from this, I was going to see how v1.8.0 of the IoT SDK behaved with get_time_ns to see if it also had the same cpu usage I saw. If the pod can be updated to work properly now I'll be able to investigate further.

[danewalton]

Yes you can roll back to the 1.5.0 version as 1.8.0 only looks to add the framework ability for Cocoapods. We otherwise haven't changed the get_time_ns implementation so you should see the same results.

[danewalton]

v1.8.0-patch-1 was released for all the cocoapods to fix the build.

[danewalton]

Hi @gutley I'm inclined to close this. Any updates here?

[gutley]

@danewalton Hi - I can still reproduce this issue, but only if I don't set a OPTION_DO_WORK_FREQUENCY_IN_MS and leave it as the default. i.e with this code, I don't have any issue:

var workFrequency = tickcounter_ms_t(100) // 100 is the maximum value - 10Hz
guard IoTHubDeviceClient_SetOption(deviceHandle, OPTION_DO_WORK_FREQUENCY_IN_MS, &workFrequency) == IOTHUB_CLIENT_OK else {
    logger.error("IoT failed to set OPTION_DO_WORK_FREQUENCY_IN_MS")

    return false
}

Without that then I see the issue.

FYI here are the other options I set:

private func configureDevice() -> Bool {
    var urlEncodeOn = true
    guard IoTHubDeviceClient_SetOption(deviceHandle, OPTION_AUTO_URL_ENCODE_DECODE, &urlEncodeOn) == IOTHUB_CLIENT_OK else {
        logger.error("IoT failed to set OPTION_AUTO_URL_ENCODE_DECODE")
        return false
    }

    guard IoTHubDeviceClient_SetRetryPolicy(deviceHandle, IOTHUB_CLIENT_RETRY_INTERVAL, 0) == IOTHUB_CLIENT_OK else {
        logger.error("IoT failed to set retry policy")
        return false
    }

    return true
}

[danewalton]

So with the default value, you see no performance drop. But if you modify the do work frequency, you see a large amount of time being taken trying to get the time?

[gutley]

@danewalton No, its the other way around - With the default value you get the performance drop.

[danewalton]

Interesting. I've tried using the default value and I don't see any performance drop on my end. Considering it goes away if you change that value and I can't get a repro, I'm inclined to close this. If there is a noticeable performance drop I would suggest slightly changing it.

[danewalton]

For reasons stated before I think we'll have to close this. I can't get the same repro and there seems to be a workaround.