This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

sd_ble_gatts_hvx duration

Sometimes when I call sd_ble_gatts_hvx, it can take several ms to return. Most of the time it takes very little time (<1ms), but occassionally it takes up to 34ms, my connection interval is 15ms, I'm not sure if related. I time the call by taking a timer count with app_timer_cnt_get before and after the call and then logging the difference converted to ms. It is my understanding that sd_ble_gatts_hvx should simply add a notification to a queue and return, not wait for space etc. Are there any reasons why sd_ble_gatts_hvx should take so long? I'm using nRF SDK 17.0.2 with S132 7.2.0 on nRF52832.

The call is being made from the main loop (app scheduler). I did wonder if softdevice interrupts were occurring during processing. Sometimes I do get BLE_GATTS_HVN_TX_COMPLETE events during the call, but not always, and the delays only occur in sd_ble_gatts_hvx, not other function calls.

0 Karl Ylvisaker over 4 years ago

Hello,

The call is being made from the main loop (app scheduler). I did wonder if softdevice interrupts were occurring during processing. Sometimes I do get BLE_GATTS_HVN_TX_COMPLETE events during the call, but not always, and the delays only occur in sd_ble_gatts_hvx, not other function calls.

You are correct in that this function call only queues the notification for sending, and therefore returns immediately. This sounds a lot like you are being interrupted between the first and second call to the app_timer ticks capture, and it therefore seems like the function is what took so long to complete. The SoftDevice will interrupt the application whenever a timing-critical event is upcoming - this is not limited to the sending of notifications either.
Since you are making this call from the main context, that means it can be interrupted by any other interrupt priority level (including the SoftDevice). What else is using interrupts in your application?

Best regards,
Karl
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

0 nrbrook over 4 years ago in reply to Karl Ylvisaker

Ok, if I run the code from an interrupt instead, it still occurs. All interrupts are priority 6 in sdk_config.h. So the interrupt must be occurring in the softdevice. But the behaviour is quite regular.

First some background info. Data is received via libuarte, processed (on the interrupt), and then notifications sent via the ble_hids library. There is very little processing occurring, and performance measurements indicate it isn't taking long. I want to get as much data out as quickly as possible when received, so we want to send multiple notifications in each connection interval. I set hvn_tx_queue_size to 10 but it only seems able to receive 3 per interval on iOS, on macOS it only receives 1 per interval.

To test, I am sending the same HID packet multiple times at once on UART, which is processed at the same time and sent on the interrupt.

ble_hids.c ble_hids_inp_rep_send has been modified as follows:

uint32_t ble_hids_inp_rep_send(ble_hids_t * p_hids,
                               uint8_t      rep_index,
                               uint16_t     len,
                               uint8_t    * p_data,
                               uint16_t     conn_handle)
{
    VERIFY_PARAM_NOT_NULL(p_hids);
    VERIFY_PARAM_NOT_NULL(p_data);

    uint32_t err_code;

    TIMERS_PERF_START(all);
    TIMERS_PERF_START(ctx);
    TIMERS_PERF_START(hvx);

    if (rep_index < p_hids->inp_rep_count)
    {
        ble_hids_rep_char_t * p_rep_char = &p_hids->inp_rep_array[rep_index];

        if (conn_handle != BLE_CONN_HANDLE_INVALID)
        {
            ble_gatts_hvx_params_t hvx_params;
            uint8_t                index   = 0;
            uint16_t               hvx_len = len;
            uint8_t              * p_host_rep_data;

            err_code = blcm_link_ctx_get(p_hids->p_link_ctx_storage,
                                         conn_handle,
                                         (void *) &p_host_rep_data);
            VERIFY_SUCCESS(err_code);
            TIMERS_PERF_END(ctx);

            p_host_rep_data += sizeof(ble_hids_client_context_t) + BOOT_KB_INPUT_REPORT_MAX_SIZE +
                               BOOT_KB_OUTPUT_REPORT_MAX_SIZE + BOOT_MOUSE_INPUT_REPORT_MAX_SIZE;

            // Store the new report data in host's context
            while (index < rep_index)
            {
                p_host_rep_data += p_hids->p_inp_rep_init_array[index].max_len;
                ++index;
            }

            if (len <= p_hids->p_inp_rep_init_array[rep_index].max_len)
            {
                memcpy(p_host_rep_data, p_data, len);
            }
            else
            {
                return NRF_ERROR_DATA_SIZE;
            }

            // Notify host
            memset(&hvx_params, 0, sizeof(hvx_params));

            hvx_params.handle = p_rep_char->char_handles.value_handle;
            hvx_params.type   = BLE_GATT_HVX_NOTIFICATION;
            hvx_params.offset = 0;
            hvx_params.p_len  = &hvx_len;
            hvx_params.p_data = p_data;

            err_code = sd_ble_gatts_hvx(conn_handle, &hvx_params);
            TIMERS_PERF_END(hvx)

            if ((err_code == NRF_SUCCESS) && (*hvx_params.p_len != len))
            {
                err_code = NRF_ERROR_DATA_SIZE;
            }
        }
        else
        {
            err_code = NRF_ERROR_INVALID_STATE;
        }
    }
    else
    {
        err_code = NRF_ERROR_INVALID_PARAM;
    }

    TIMERS_PERF_END(all);
    return err_code;
}

The TIMERS_PERF_START macro stores the current timestamp, and TIMERS_PERF_END takes the current timestamp, calculates the difference and prints a log. Implementation:

typedef uint32_t timers_perf_value;

timers_perf_value timers_perf_measure_start(void);

#define TIMERS_PERF_START(_name) timers_perf_value _name##_val = timers_perf_measure_start();

void timers_perf_measure_end_log(timers_perf_value value, char const *name);

#define TIMERS_PERF_END(_name) timers_perf_measure_end_log(_name##_val, #_name);

static uint32_t app_timer_ms(uint32_t ticks)
{
    // eg. (7 + 1) * 1000 / 32768
    //   = 8000 / 32768
    //   = 0.24414062
    const float numerator = ((float)APP_TIMER_CONFIG_RTC_FREQUENCY + 1.0f) * 1000.0f;
    const float denominator = (float)APP_TIMER_CLOCK_FREQ;
    const float ms_per_tick = numerator / denominator;

    uint32_t ms = (uint32_t)(ms_per_tick * (float)ticks);

    return ms;
}

timers_perf_value timers_perf_measure_start(void) {
    return app_timer_cnt_get();
}

void timers_perf_measure_end_log(timers_perf_value value, char const *name) {
    uint32_t end = app_timer_cnt_get();
    NRF_LOG_INFO("PERF %s start %dms end %dms diff %dms", name, app_timer_ms(value), app_timer_ms(end), app_timer_ms(app_timer_cnt_diff_compute(end, value)));
}

Here is a sample of our logs when connected to macOS (1 notification received per interval):

00> [00:00:26.286,895] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:26.287,048] <info> Timers: PERF ctx start 26287ms end 26287ms diff 0ms
00> [00:00:26.287,261] <info> Timers: PERF hvx start 26287ms end 26287ms diff 0ms
00> [00:00:26.287,445] <info> Timers: PERF all start 26287ms end 26287ms diff 0ms
00> [00:00:26.287,628] <debug> BTFW: Processed 7 bytes
00> [00:00:26.287,872] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:26.288,024] <info> Timers: PERF ctx start 26288ms end 26288ms diff 0ms
00> [00:00:26.288,238] <info> Timers: PERF hvx start 26288ms end 26288ms diff 0ms
00> [00:00:26.288,421] <info> Timers: PERF all start 26288ms end 26288ms diff 0ms
00> [00:00:26.288,635] <debug> BTFW: Processed 7 bytes
00> [00:00:26.288,848] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:26.289,001] <info> Timers: PERF ctx start 26289ms end 26289ms diff 0ms
00> [00:00:26.289,215] <info> Timers: PERF hvx start 26289ms end 26289ms diff 0ms
00> [00:00:26.307,220] <info> Timers: PERF all start 26289ms end 26307ms diff 18ms
00> [00:00:26.307,434] <debug> BTFW: Processed 7 bytes
00> [00:00:26.307,678] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:26.307,830] <info> Timers: PERF ctx start 26307ms end 26307ms diff 0ms
00> [00:00:26.308,044] <info> Timers: PERF hvx start 26307ms end 26308ms diff 0ms
00> [00:00:26.308,227] <info> Timers: PERF all start 26307ms end 26308ms diff 0ms
00> [00:00:26.308,410] <debug> BTFW: Processed 7 bytes
00> [00:00:26.308,654] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:26.308,807] <info> Timers: PERF ctx start 26308ms end 26308ms diff 0ms
00> [00:00:26.309,020] <info> Timers: PERF hvx start 26308ms end 26309ms diff 0ms
00> [00:00:26.309,204] <info> Timers: PERF all start 26308ms end 26309ms diff 0ms
00> [00:00:26.309,387] <debug> BTFW: Processed 7 bytes
00> [00:00:26.309,631] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:26.309,783] <info> Timers: PERF ctx start 26309ms end 26309ms diff 0ms
00> [00:00:26.343,658] <info> Timers: PERF hvx start 26309ms end 26343ms diff 33ms
00> [00:00:26.343,841] <info> Timers: PERF all start 26309ms end 26343ms diff 34ms
00> [00:00:26.344,085] <debug> BTFW: Processed 7 bytes
00> [00:00:26.344,421] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:26.344,573] <info> Timers: PERF ctx start 26344ms end 26344ms diff 0ms
00> [00:00:26.344,787] <info> Timers: PERF hvx start 26344ms end 26344ms diff 0ms
00> [00:00:26.344,970] <info> Timers: PERF all start 26344ms end 26344ms diff 0ms
00> [00:00:26.345,153] <debug> BTFW: Processed 7 bytes
00> [00:00:26.345,397] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:26.345,550] <info> Timers: PERF ctx start 26345ms end 26345ms diff 0ms
00> [00:00:26.345,764] <info> Timers: PERF hvx start 26345ms end 26345ms diff 0ms
00> [00:00:26.345,947] <info> Timers: PERF all start 26345ms end 26345ms diff 0ms
00> [00:00:26.346,160] <debug> BTFW: Processed 7 bytes
00> [00:00:26.377,075] <debug> BTFW: Processed 1 bytes

00> [00:00:31.765,380] <debug> BTFW: Received 57 bytes
00> [00:00:31.765,625] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:31.765,777] <info> Timers: PERF ctx start 31765ms end 31765ms diff 0ms
00> [00:00:31.766,021] <info> Timers: PERF hvx start 31765ms end 31765ms diff 0ms
00> [00:00:31.766,174] <info> Timers: PERF all start 31765ms end 31766ms diff 0ms
00> [00:00:31.766,387] <debug> BTFW: Processed 7 bytes
00> [00:00:31.766,693] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:31.766,967] <info> Timers: PERF ctx start 31766ms end 31766ms diff 0ms
00> [00:00:31.767,181] <info> Timers: PERF hvx start 31766ms end 31767ms diff 0ms
00> [00:00:31.767,333] <info> Timers: PERF all start 31766ms end 31767ms diff 0ms
00> [00:00:31.767,547] <debug> BTFW: Processed 7 bytes
00> [00:00:31.767,761] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:31.767,944] <info> Timers: PERF ctx start 31767ms end 31767ms diff 0ms
00> [00:00:31.768,157] <info> Timers: PERF hvx start 31767ms end 31768ms diff 0ms
00> [00:00:31.779,754] <info> Timers: PERF all start 31767ms end 31779ms diff 11ms
00> [00:00:31.779,968] <debug> BTFW: Processed 7 bytes
00> [00:00:31.780,212] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:31.780,364] <info> Timers: PERF ctx start 31780ms end 31780ms diff 0ms
00> [00:00:31.780,578] <info> Timers: PERF hvx start 31780ms end 31780ms diff 0ms
00> [00:00:31.780,731] <info> Timers: PERF all start 31780ms end 31780ms diff 0ms
00> [00:00:31.780,944] <debug> BTFW: Processed 7 bytes
00> [00:00:31.781,188] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:31.781,341] <info> Timers: PERF ctx start 31781ms end 31781ms diff 0ms
00> [00:00:31.781,555] <info> Timers: PERF hvx start 31781ms end 31781ms diff 0ms
00> [00:00:31.781,707] <info> Timers: PERF all start 31781ms end 31781ms diff 0ms
00> [00:00:31.781,921] <debug> BTFW: Processed 7 bytes
00> [00:00:31.782,165] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:31.782,318] <info> Timers: PERF ctx start 31782ms end 31782ms diff 0ms
00> [00:00:31.817,260] <info> Timers: PERF hvx start 31782ms end 31817ms diff 34ms
00> [00:00:31.817,413] <info> Timers: PERF all start 31782ms end 31817ms diff 35ms
00> [00:00:31.817,626] <debug> BTFW: Processed 7 bytes
00> [00:00:31.817,840] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:31.818,023] <info> Timers: PERF ctx start 31818ms end 31818ms diff 0ms
00> [00:00:31.818,237] <info> Timers: PERF hvx start 31818ms end 31818ms diff 0ms
00> [00:00:31.818,389] <info> Timers: PERF all start 31817ms end 31818ms diff 0ms
00> [00:00:31.818,603] <debug> BTFW: Processed 7 bytes
00> [00:00:31.818,847] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:31.819,000] <info> Timers: PERF ctx start 31819ms end 31819ms diff 0ms
00> [00:00:31.819,213] <info> Timers: PERF hvx start 31819ms end 31819ms diff 0ms
00> [00:00:31.819,366] <info> Timers: PERF all start 31819ms end 31819ms diff 0ms
00> [00:00:31.819,580] <debug> BTFW: Processed 7 bytes
00> [00:00:31.856,231] <debug> BTFW: Processed 1 bytes

00> [00:00:37.429,412] <debug> BTFW: Received 57 bytes
00> [00:00:37.429,656] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:37.429,809] <info> Timers: PERF ctx start 37429ms end 37429ms diff 0ms
00> [00:00:37.430,023] <info> Timers: PERF hvx start 37429ms end 37430ms diff 0ms
00> [00:00:37.430,206] <info> Timers: PERF all start 37429ms end 37430ms diff 0ms
00> [00:00:37.430,389] <debug> BTFW: Processed 7 bytes
00> [00:00:37.430,633] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:37.430,786] <info> Timers: PERF ctx start 37430ms end 37430ms diff 0ms
00> [00:00:37.431,030] <info> Timers: PERF hvx start 37430ms end 37431ms diff 0ms
00> [00:00:37.431,182] <info> Timers: PERF all start 37430ms end 37431ms diff 0ms
00> [00:00:37.431,396] <debug> BTFW: Processed 7 bytes
00> [00:00:37.431,610] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:37.431,762] <info> Timers: PERF ctx start 37431ms end 37431ms diff 0ms
00> [00:00:37.432,006] <info> Timers: PERF hvx start 37431ms end 37431ms diff 0ms
00> [00:00:37.447,906] <info> Timers: PERF all start 37431ms end 37447ms diff 16ms
00> [00:00:37.448,120] <debug> BTFW: Processed 7 bytes
00> [00:00:37.448,333] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:37.448,516] <info> Timers: PERF ctx start 37448ms end 37448ms diff 0ms
00> [00:00:37.448,730] <info> Timers: PERF hvx start 37448ms end 37448ms diff 0ms
00> [00:00:37.448,883] <info> Timers: PERF all start 37448ms end 37448ms diff 0ms
00> [00:00:37.449,096] <debug> BTFW: Processed 7 bytes
00> [00:00:37.449,310] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:37.449,493] <info> Timers: PERF ctx start 37449ms end 37449ms diff 0ms
00> [00:00:37.449,707] <info> Timers: PERF hvx start 37449ms end 37449ms diff 0ms
00> [00:00:37.449,859] <info> Timers: PERF all start 37449ms end 37449ms diff 0ms
00> [00:00:37.450,073] <debug> BTFW: Processed 7 bytes
00> [00:00:37.450,317] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:37.450,469] <info> Timers: PERF ctx start 37450ms end 37450ms diff 0ms
00> [00:00:37.485,717] <info> Timers: PERF hvx start 37450ms end 37485ms diff 35ms
00> [00:00:37.485,870] <info> Timers: PERF all start 37450ms end 37485ms diff 35ms
00> [00:00:37.486,083] <debug> BTFW: Processed 7 bytes
00> [00:00:37.486,297] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:37.486,480] <info> Timers: PERF ctx start 37486ms end 37486ms diff 0ms
00> [00:00:37.486,694] <info> Timers: PERF hvx start 37486ms end 37486ms diff 0ms
00> [00:00:37.486,846] <info> Timers: PERF all start 37486ms end 37486ms diff 0ms
00> [00:00:37.487,060] <debug> BTFW: Processed 7 bytes
00> [00:00:37.487,274] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:37.487,457] <info> Timers: PERF ctx start 37487ms end 37487ms diff 0ms
00> [00:00:37.487,670] <info> Timers: PERF hvx start 37487ms end 37487ms diff 0ms
00> [00:00:37.487,823] <info> Timers: PERF all start 37487ms end 37487ms diff 0ms
00> [00:00:37.488,037] <debug> BTFW: Processed 7 bytes
00> [00:00:37.528,839] <debug> BTFW: Processed 1 bytes

00> [00:00:42.100,463] <debug> BTFW: Received 57 bytes
00> [00:00:42.100,708] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:42.100,860] <info> Timers: PERF ctx start 42100ms end 42100ms diff 0ms
00> [00:00:42.101,074] <info> Timers: PERF hvx start 42100ms end 42101ms diff 0ms
00> [00:00:42.101,257] <info> Timers: PERF all start 42100ms end 42101ms diff 0ms
00> [00:00:42.101,440] <debug> BTFW: Processed 7 bytes
00> [00:00:42.101,684] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:42.101,837] <info> Timers: PERF ctx start 42101ms end 42101ms diff 0ms
00> [00:00:42.102,050] <info> Timers: PERF hvx start 42101ms end 42102ms diff 0ms
00> [00:00:42.102,233] <info> Timers: PERF all start 42101ms end 42102ms diff 0ms
00> [00:00:42.102,447] <debug> BTFW: Processed 7 bytes
00> [00:00:42.102,661] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:42.102,813] <info> Timers: PERF ctx start 42102ms end 42102ms diff 0ms
00> [00:00:42.103,057] <info> Timers: PERF hvx start 42102ms end 42103ms diff 0ms
00> [00:00:42.118,225] <info> Timers: PERF all start 42102ms end 42118ms diff 15ms
00> [00:00:42.118,438] <debug> BTFW: Processed 7 bytes
00> [00:00:42.118,652] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:42.118,835] <info> Timers: PERF ctx start 42118ms end 42118ms diff 0ms
00> [00:00:42.119,049] <info> Timers: PERF hvx start 42118ms end 42119ms diff 0ms
00> [00:00:42.119,201] <info> Timers: PERF all start 42118ms end 42119ms diff 0ms
00> [00:00:42.119,415] <debug> BTFW: Processed 7 bytes
00> [00:00:42.119,628] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:42.119,812] <info> Timers: PERF ctx start 42119ms end 42119ms diff 0ms
00> [00:00:42.120,025] <info> Timers: PERF hvx start 42119ms end 42120ms diff 0ms
00> [00:00:42.120,178] <info> Timers: PERF all start 42119ms end 42120ms diff 0ms
00> [00:00:42.120,391] <debug> BTFW: Processed 7 bytes
00> [00:00:42.120,605] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:42.120,788] <info> Timers: PERF ctx start 42120ms end 42120ms diff 0ms
00> [00:00:42.161,590] <info> Timers: PERF hvx start 42120ms end 42161ms diff 40ms
00> [00:00:42.161,773] <info> Timers: PERF all start 42120ms end 42161ms diff 41ms
00> [00:00:42.162,139] <debug> BTFW: Processed 7 bytes
00> [00:00:42.162,353] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:42.162,536] <info> Timers: PERF ctx start 42162ms end 42162ms diff 0ms
00> [00:00:42.162,750] <info> Timers: PERF hvx start 42162ms end 42162ms diff 0ms
00> [00:00:42.162,902] <info> Timers: PERF all start 42162ms end 42162ms diff 0ms
00> [00:00:42.163,116] <debug> BTFW: Processed 7 bytes
00> [00:00:42.163,330] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:42.163,513] <info> Timers: PERF ctx start 42163ms end 42163ms diff 0ms
00> [00:00:42.163,726] <info> Timers: PERF hvx start 42163ms end 42163ms diff 0ms
00> [00:00:42.163,879] <info> Timers: PERF all start 42163ms end 42163ms diff 0ms
00> [00:00:42.164,093] <debug> BTFW: Processed 7 bytes
00> [00:00:42.199,218] <debug> BTFW: Processed 1 bytes

00> [00:00:52.451,141] <debug> BTFW: Received 27 bytes
00> [00:00:52.451,354] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:52.451,538] <info> Timers: PERF ctx start 52451ms end 52451ms diff 0ms
00> [00:00:52.451,751] <info> Timers: PERF hvx start 52451ms end 52451ms diff 0ms
00> [00:00:52.451,904] <info> Timers: PERF all start 52451ms end 52451ms diff 0ms
00> [00:00:52.452,117] <debug> BTFW: Processed 7 bytes
00> [00:00:52.452,331] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:52.452,514] <info> Timers: PERF ctx start 52452ms end 52452ms diff 0ms
00> [00:00:52.452,728] <info> Timers: PERF hvx start 52452ms end 52452ms diff 0ms
00> [00:00:52.452,880] <info> Timers: PERF all start 52452ms end 52452ms diff 0ms
00> [00:00:52.453,094] <debug> BTFW: Processed 7 bytes
00> [00:00:52.453,308] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:52.453,491] <info> Timers: PERF ctx start 52453ms end 52453ms diff 0ms
00> [00:00:52.453,704] <info> Timers: PERF hvx start 52453ms end 52453ms diff 0ms
00> [00:00:52.464,782] <info> Timers: PERF all start 52453ms end 52464ms diff 11ms
00> [00:00:52.464,996] <debug> BTFW: Processed 7 bytes
00> [00:00:52.465,179] <debug> BTFW: Received 30 bytes
00> [00:00:52.465,423] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:52.465,606] <info> Timers: PERF ctx start 52465ms end 52465ms diff 0ms
00> [00:00:52.465,881] <info> Timers: PERF hvx start 52465ms end 52465ms diff 0ms
00> [00:00:52.466,094] <info> Timers: PERF all start 52465ms end 52466ms diff 0ms
00> [00:00:52.466,461] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:52.466,644] <info> Timers: PERF ctx start 52466ms end 52466ms diff 0ms
00> [00:00:52.466,857] <info> Timers: PERF hvx start 52466ms end 52466ms diff 0ms
00> [00:00:52.467,010] <info> Timers: PERF all start 52466ms end 52467ms diff 0ms
00> [00:00:52.467,224] <debug> BTFW: Processed 7 bytes
00> [00:00:52.467,437] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:52.467,620] <info> Timers: PERF ctx start 52467ms end 52467ms diff 0ms
00> [00:00:52.505,737] <info> Timers: PERF hvx start 52467ms end 52505ms diff 38ms
00> [00:00:52.505,920] <info> Timers: PERF all start 52467ms end 52505ms diff 38ms
00> [00:00:52.506,103] <debug> BTFW: Processed 7 bytes
00> [00:00:52.506,347] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:52.506,500] <info> Timers: PERF ctx start 52506ms end 52506ms diff 0ms
00> [00:00:52.506,713] <info> Timers: PERF hvx start 52506ms end 52506ms diff 0ms
00> [00:00:52.506,896] <info> Timers: PERF all start 52506ms end 52506ms diff 0ms
00> [00:00:52.507,080] <debug> BTFW: Processed 7 bytes
00> [00:00:52.507,324] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:52.507,476] <info> Timers: PERF ctx start 52507ms end 52507ms diff 0ms
00> [00:00:52.507,720] <info> Timers: PERF hvx start 52507ms end 52507ms diff 0ms
00> [00:00:52.507,873] <info> Timers: PERF all start 52507ms end 52507ms diff 0ms
00> [00:00:52.508,087] <debug> BTFW: Processed 7 bytes
00> [00:00:52.545,562] <debug> BTFW: Processed 1 bytes

00> [00:00:56.564,544] <debug> BTFW: Received 57 bytes
00> [00:00:56.564,788] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:56.564,941] <info> Timers: PERF ctx start 56564ms end 56564ms diff 0ms
00> [00:00:56.565,155] <info> Timers: PERF hvx start 56564ms end 56565ms diff 0ms
00> [00:00:56.565,338] <info> Timers: PERF all start 56564ms end 56565ms diff 0ms
00> [00:00:56.565,551] <debug> BTFW: Processed 7 bytes
00> [00:00:56.565,765] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:56.565,917] <info> Timers: PERF ctx start 56565ms end 56565ms diff 0ms
00> [00:00:56.566,162] <info> Timers: PERF hvx start 56565ms end 56566ms diff 0ms
00> [00:00:56.566,314] <info> Timers: PERF all start 56565ms end 56566ms diff 0ms
00> [00:00:56.566,528] <debug> BTFW: Processed 7 bytes
00> [00:00:56.566,741] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:56.566,925] <info> Timers: PERF ctx start 56566ms end 56566ms diff 0ms
00> [00:00:56.567,138] <info> Timers: PERF hvx start 56566ms end 56567ms diff 0ms
00> [00:00:56.578,521] <info> Timers: PERF all start 56566ms end 56578ms diff 11ms
00> [00:00:56.578,735] <debug> BTFW: Processed 7 bytes
00> [00:00:56.578,979] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:56.579,132] <info> Timers: PERF ctx start 56579ms end 56579ms diff 0ms
00> [00:00:56.579,345] <info> Timers: PERF hvx start 56579ms end 56579ms diff 0ms
00> [00:00:56.579,528] <info> Timers: PERF all start 56579ms end 56579ms diff 0ms
00> [00:00:56.579,711] <debug> BTFW: Processed 7 bytes
00> [00:00:56.579,956] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:56.580,108] <info> Timers: PERF ctx start 56580ms end 56580ms diff 0ms
00> [00:00:56.580,322] <info> Timers: PERF hvx start 56580ms end 56580ms diff 0ms
00> [00:00:56.580,505] <info> Timers: PERF all start 56580ms end 56580ms diff 0ms
00> [00:00:56.580,688] <debug> BTFW: Processed 7 bytes
00> [00:00:56.580,932] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:56.581,085] <info> Timers: PERF ctx start 56581ms end 56581ms diff 0ms
00> [00:00:56.611,755] <info> Timers: PERF hvx start 56581ms end 56611ms diff 30ms
00> [00:00:56.611,907] <info> Timers: PERF all start 56581ms end 56611ms diff 30ms
00> [00:00:56.612,121] <debug> BTFW: Processed 7 bytes
00> [00:00:56.612,365] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:56.612,518] <info> Timers: PERF ctx start 56612ms end 56612ms diff 0ms
00> [00:00:56.612,731] <info> Timers: PERF hvx start 56612ms end 56612ms diff 0ms
00> [00:00:56.612,884] <info> Timers: PERF all start 56612ms end 56612ms diff 0ms
00> [00:00:56.613,098] <debug> BTFW: Processed 7 bytes
00> [00:00:56.613,342] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:00:56.613,494] <info> Timers: PERF ctx start 56613ms end 56613ms diff 0ms
00> [00:00:56.613,708] <info> Timers: PERF hvx start 56613ms end 56613ms diff 0ms
00> [00:00:56.613,891] <info> Timers: PERF all start 56613ms end 56613ms diff 0ms

You can see from the logs, the delay is occurring at regular points – in the third notification send there is a delay of 0-20ms, and in the 6th notification there is a delay of 30-34ms. However, the third notification delay appears not to occur in the hvx call.

Here is a sample when connected to iOS:

00> [00:01:36.674,438] <debug> BTFW: Received 54 bytes
00> [00:01:36.674,682] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:36.674,835] <info> Timers: PERF ctx start 96674ms end 96674ms diff 0ms
00> [00:01:36.675,140] <info> Timers: PERF hvx start 96674ms end 96675ms diff 0ms
00> [00:01:36.675,292] <info> Timers: PERF all start 96674ms end 96675ms diff 0ms
00> [00:01:36.675,506] <debug> BTFW: Processed 7 bytes
00> [00:01:36.675,720] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:36.675,903] <info> Timers: PERF ctx start 96675ms end 96675ms diff 0ms
00> [00:01:36.676,116] <info> Timers: PERF hvx start 96675ms end 96676ms diff 0ms
00> [00:01:36.676,269] <info> Timers: PERF all start 96675ms end 96676ms diff 0ms
00> [00:01:36.676,483] <debug> BTFW: Processed 7 bytes
00> [00:01:36.676,696] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:36.676,879] <info> Timers: PERF ctx start 96676ms end 96676ms diff 0ms
00> [00:01:36.677,093] <info> Timers: PERF hvx start 96676ms end 96677ms diff 0ms
00> [00:01:36.689,117] <info> Timers: PERF all start 96676ms end 96689ms diff 12ms
00> [00:01:36.689,331] <debug> BTFW: Processed 7 bytes
00> [00:01:36.689,575] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:36.689,727] <info> Timers: PERF ctx start 96689ms end 96689ms diff 0ms
00> [00:01:36.689,941] <info> Timers: PERF hvx start 96689ms end 96689ms diff 0ms
00> [00:01:36.690,093] <info> Timers: PERF all start 96689ms end 96690ms diff 0ms
00> [00:01:36.690,307] <debug> BTFW: Processed 7 bytes
00> [00:01:36.690,551] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:36.690,704] <info> Timers: PERF ctx start 96690ms end 96690ms diff 0ms
00> [00:01:36.690,917] <info> Timers: PERF hvx start 96690ms end 96690ms diff 0ms
00> [00:01:36.691,070] <info> Timers: PERF all start 96690ms end 96691ms diff 0ms
00> [00:01:36.691,284] <debug> BTFW: Processed 7 bytes
00> [00:01:36.691,528] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:36.691,680] <info> Timers: PERF ctx start 96691ms end 96691ms diff 0ms
00> [00:01:36.727,447] <info> Timers: PERF hvx start 96691ms end 96727ms diff 35ms
00> [00:01:36.727,600] <info> Timers: PERF all start 96691ms end 96727ms diff 35ms
00> [00:01:36.727,813] <debug> BTFW: Processed 7 bytes
00> [00:01:36.728,057] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:36.728,210] <info> Timers: PERF ctx start 96728ms end 96728ms diff 0ms
00> [00:01:36.728,424] <info> Timers: PERF hvx start 96728ms end 96728ms diff 0ms
00> [00:01:36.728,576] <info> Timers: PERF all start 96728ms end 96728ms diff 0ms
00> [00:01:36.728,790] <debug> BTFW: Processed 7 bytes
00> [00:01:36.729,187] <debug> BTFW: Received 3 bytes
00> [00:01:36.729,400] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:36.729,583] <info> Timers: PERF ctx start 96729ms end 96729ms diff 0ms
00> [00:01:36.729,797] <info> Timers: PERF hvx start 96729ms end 96729ms diff 0ms
00> [00:01:36.729,949] <info> Timers: PERF all start 96729ms end 96729ms diff 0ms
00> [00:01:36.769,348] <debug> BTFW: Processed 1 bytes

00> [00:01:38.695,648] <debug> BTFW: Received 57 bytes
00> [00:01:38.695,892] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:38.696,044] <info> Timers: PERF ctx start 98696ms end 98696ms diff 0ms
00> [00:01:38.696,258] <info> Timers: PERF hvx start 98696ms end 98696ms diff 0ms
00> [00:01:38.696,441] <info> Timers: PERF all start 98696ms end 98696ms diff 0ms
00> [00:01:38.696,655] <debug> BTFW: Processed 7 bytes
00> [00:01:38.696,868] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:38.697,021] <info> Timers: PERF ctx start 98697ms end 98697ms diff 0ms
00> [00:01:38.697,265] <info> Timers: PERF hvx start 98697ms end 98697ms diff 0ms
00> [00:01:38.697,418] <info> Timers: PERF all start 98697ms end 98697ms diff 0ms
00> [00:01:38.697,631] <debug> BTFW: Processed 7 bytes
00> [00:01:38.697,845] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:38.698,028] <info> Timers: PERF ctx start 98698ms end 98698ms diff 0ms
00> [00:01:38.698,242] <info> Timers: PERF hvx start 98698ms end 98698ms diff 0ms
00> [00:01:38.716,583] <info> Timers: PERF all start 98698ms end 98716ms diff 18ms
00> [00:01:38.716,766] <debug> BTFW: Processed 7 bytes
00> [00:01:38.717,010] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:38.717,163] <info> Timers: PERF ctx start 98717ms end 98717ms diff 0ms
00> [00:01:38.717,376] <info> Timers: PERF hvx start 98717ms end 98717ms diff 0ms
00> [00:01:38.717,559] <info> Timers: PERF all start 98717ms end 98717ms diff 0ms
00> [00:01:38.717,742] <debug> BTFW: Processed 7 bytes
00> [00:01:38.717,987] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:38.718,139] <info> Timers: PERF ctx start 98718ms end 98718ms diff 0ms
00> [00:01:38.718,353] <info> Timers: PERF hvx start 98718ms end 98718ms diff 0ms
00> [00:01:38.718,536] <info> Timers: PERF all start 98718ms end 98718ms diff 0ms
00> [00:01:38.718,719] <debug> BTFW: Processed 7 bytes
00> [00:01:38.718,963] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:38.719,177] <info> Timers: PERF ctx start 98719ms end 98719ms diff 0ms
00> [00:01:38.754,943] <info> Timers: PERF hvx start 98719ms end 98754ms diff 35ms
00> [00:01:38.755,126] <info> Timers: PERF all start 98719ms end 98755ms diff 35ms
00> [00:01:38.755,310] <debug> BTFW: Processed 7 bytes
00> [00:01:38.755,554] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:38.755,706] <info> Timers: PERF ctx start 98755ms end 98755ms diff 0ms
00> [00:01:38.755,920] <info> Timers: PERF hvx start 98755ms end 98755ms diff 0ms
00> [00:01:38.756,103] <info> Timers: PERF all start 98755ms end 98756ms diff 0ms
00> [00:01:38.756,286] <debug> BTFW: Processed 7 bytes
00> [00:01:38.756,530] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:38.756,683] <info> Timers: PERF ctx start 98756ms end 98756ms diff 0ms
00> [00:01:38.756,896] <info> Timers: PERF hvx start 98756ms end 98756ms diff 0ms
00> [00:01:38.757,080] <info> Timers: PERF all start 98756ms end 98757ms diff 0ms
00> [00:01:38.757,293] <debug> BTFW: Processed 7 bytes
00> [00:01:38.798,461] <debug> BTFW: Processed 1 bytes

00> [00:01:40.600,585] <debug> BTFW: Received 57 bytes
00> [00:01:40.600,830] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:40.600,982] <info> Timers: PERF ctx start 100600ms end 100600ms diff 0ms
00> [00:01:40.601,226] <info> Timers: PERF hvx start 100600ms end 100601ms diff 0ms
00> [00:01:40.601,379] <info> Timers: PERF all start 100600ms end 100601ms diff 0ms
00> [00:01:40.601,593] <debug> BTFW: Processed 7 bytes
00> [00:01:40.601,806] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:40.601,989] <info> Timers: PERF ctx start 100601ms end 100601ms diff 0ms
00> [00:01:40.602,203] <info> Timers: PERF hvx start 100601ms end 100602ms diff 0ms
00> [00:01:40.602,355] <info> Timers: PERF all start 100601ms end 100602ms diff 0ms
00> [00:01:40.602,569] <debug> BTFW: Processed 7 bytes
00> [00:01:40.602,813] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:40.602,966] <info> Timers: PERF ctx start 100602ms end 100602ms diff 0ms
00> [00:01:40.603,179] <info> Timers: PERF hvx start 100602ms end 100603ms diff 0ms
00> [00:01:40.618,682] <info> Timers: PERF all start 100602ms end 100618ms diff 15ms
00> [00:01:40.618,896] <debug> BTFW: Processed 7 bytes
00> [00:01:40.619,140] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:40.619,293] <info> Timers: PERF ctx start 100619ms end 100619ms diff 0ms
00> [00:01:40.619,506] <info> Timers: PERF hvx start 100619ms end 100619ms diff 0ms
00> [00:01:40.619,689] <info> Timers: PERF all start 100619ms end 100619ms diff 0ms
00> [00:01:40.619,903] <debug> BTFW: Processed 7 bytes
00> [00:01:40.620,117] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:40.620,269] <info> Timers: PERF ctx start 100620ms end 100620ms diff 0ms
00> [00:01:40.620,513] <info> Timers: PERF hvx start 100620ms end 100620ms diff 0ms
00> [00:01:40.620,666] <info> Timers: PERF all start 100620ms end 100620ms diff 0ms
00> [00:01:40.620,880] <debug> BTFW: Processed 7 bytes
00> [00:01:40.621,093] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:40.660,675] <info> Timers: PERF ctx start 100660ms end 100660ms diff 0ms
00> [00:01:40.660,980] <info> Timers: PERF hvx start 100660ms end 100660ms diff 0ms
00> [00:01:40.661,132] <info> Timers: PERF all start 100660ms end 100661ms diff 0ms
00> [00:01:40.661,346] <debug> BTFW: Processed 7 bytes
00> [00:01:40.661,560] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:40.661,743] <info> Timers: PERF ctx start 100661ms end 100661ms diff 0ms
00> [00:01:40.661,956] <info> Timers: PERF hvx start 100661ms end 100661ms diff 0ms
00> [00:01:40.662,109] <info> Timers: PERF all start 100661ms end 100662ms diff 0ms
00> [00:01:40.662,322] <debug> BTFW: Processed 7 bytes
00> [00:01:40.662,567] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:40.662,719] <info> Timers: PERF ctx start 100662ms end 100662ms diff 0ms
00> [00:01:40.662,933] <info> Timers: PERF hvx start 100662ms end 100662ms diff 0ms
00> [00:01:40.663,116] <info> Timers: PERF all start 100662ms end 100663ms diff 0ms
00> [00:01:40.697,448] <debug> BTFW: Processed 7 bytes
00> [00:01:40.697,601] <debug> BTFW: Processed 1 bytes

00> [00:01:41.918,579] <debug> BTFW: Received 57 bytes
00> [00:01:41.918,823] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:41.918,975] <info> Timers: PERF ctx start 101918ms end 101918ms diff 0ms
00> [00:01:41.919,281] <info> Timers: PERF hvx start 101918ms end 101919ms diff 0ms
00> [00:01:41.919,464] <info> Timers: PERF all start 101918ms end 101919ms diff 0ms
00> [00:01:41.919,647] <debug> BTFW: Processed 7 bytes
00> [00:01:41.919,891] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:41.920,043] <info> Timers: PERF ctx start 101920ms end 101920ms diff 0ms
00> [00:01:41.920,257] <info> Timers: PERF hvx start 101920ms end 101920ms diff 0ms
00> [00:01:41.920,440] <info> Timers: PERF all start 101920ms end 101920ms diff 0ms
00> [00:01:41.920,654] <debug> BTFW: Processed 7 bytes
00> [00:01:41.920,867] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:41.921,051] <info> Timers: PERF ctx start 101921ms end 101921ms diff 0ms
00> [00:01:41.921,264] <info> Timers: PERF hvx start 101921ms end 101921ms diff 0ms
00> [00:01:41.930,206] <info> Timers: PERF all start 101921ms end 101930ms diff 9ms
00> [00:01:41.930,450] <debug> BTFW: Processed 7 bytes
00> [00:01:41.930,786] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:41.931,030] <info> Timers: PERF ctx start 101931ms end 101931ms diff 0ms
00> [00:01:41.931,304] <info> Timers: PERF hvx start 101931ms end 101931ms diff 0ms
00> [00:01:41.931,549] <info> Timers: PERF all start 101931ms end 101931ms diff 0ms
00> [00:01:41.931,915] <debug> BTFW: Processed 7 bytes
00> [00:01:41.932,159] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:41.932,312] <info> Timers: PERF ctx start 101932ms end 101932ms diff 0ms
00> [00:01:41.932,525] <info> Timers: PERF hvx start 101932ms end 101932ms diff 0ms
00> [00:01:41.932,708] <info> Timers: PERF all start 101932ms end 101932ms diff 0ms
00> [00:01:41.932,891] <debug> BTFW: Processed 7 bytes
00> [00:01:41.933,135] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:41.970,520] <info> Timers: PERF ctx start 101970ms end 101970ms diff 0ms
00> [00:01:41.970,825] <info> Timers: PERF hvx start 101970ms end 101970ms diff 0ms
00> [00:01:41.971,008] <info> Timers: PERF all start 101970ms end 101970ms diff 0ms
00> [00:01:41.971,191] <debug> BTFW: Processed 7 bytes
00> [00:01:41.971,435] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:41.971,588] <info> Timers: PERF ctx start 101971ms end 101971ms diff 0ms
00> [00:01:41.971,801] <info> Timers: PERF hvx start 101971ms end 101971ms diff 0ms
00> [00:01:41.971,984] <info> Timers: PERF all start 101971ms end 101971ms diff 0ms
00> [00:01:41.972,198] <debug> BTFW: Processed 7 bytes
00> [00:01:41.972,412] <info> BTFW: Processing raw report data length 5 descriptor 2: 0x00...
00> [00:01:41.972,595] <info> Timers: PERF ctx start 101972ms end 101972ms diff 0ms
00> [00:01:41.972,808] <info> Timers: PERF hvx start 101972ms end 101972ms diff 0ms
00> [00:01:41.972,961] <info> Timers: PERF all start 101972ms end 101972ms diff 0ms
00> [00:01:42.009,643] <debug> BTFW: Processed 7 bytes
00> [00:01:42.009,796] <debug> BTFW: Processed 1 bytes

Here are the received packets on iOS:

Jul Jul 22 12:34:16.783  ATT Receive Jul 22 12:34:16.783  ATT Receive Jul 22 12:34:16.796  ATT Receive Jul 22 12:34:16.796  ATT Receive Jul 22 12:34:16.841  ATT Receive Jul 22 12:34:16.842  ATT Receive Jul 22 12:34:16.842  ATT Receive Jul 22 12:34:18.806  ATT Receive Jul 22 12:34:18.806  ATT Receive Jul 22 12:34:18.807  ATT Receive Jul 22 12:34:18.821  ATT Receive Jul 22 12:34:18.821  ATT Receive Jul 22 12:34:18.866  ATT Receive Jul 22 12:34:18.866  ATT Receive Jul 22 12:34:18.867  ATT Receive Jul 22 12:34:20.712  ATT Receive Jul 22 12:34:20.712  ATT Receive Jul 22 12:34:20.713  ATT Receive Jul 22 12:34:20.729  ATT Receive Jul 22 12:34:20.729  ATT Receive Jul 22 12:34:20.772  ATT Receive Jul 22 12:34:20.772  ATT Receive Jul 22 12:34:20.772  ATT Receive Jul 22 12:34:22.031  ATT Receive Jul 22 12:34:22.031  ATT Receive Jul 22 12:34:22.032  ATT Receive Jul 22 12:34:22.046  ATT Receive Jul 22 12:34:22.047  ATT Receive Jul 22 12:34:22.076  ATT Receive Jul 22 12:34:22.077  ATT Receive Jul 22 12:34:22.077  ATT Receive

22 12:34:16.781 ATT Receive 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000 0x005C 00:00:00:00:00:00 Handle Value Notification - Handle:0x0025 - Value: 0010 1000

You can see that in most cases 2 or 3 notifications are received per interval (interval=15ms), and while there is still a delay in the 3rd notification sent (10-20ms), sometimes the 6th notification has no delay. This indicates that interrupts are occurring in the softdevice during execution which take 1-2 connection intervals to process. Is there any way to reduce this delay?

0 Simonr over 4 years ago

Hi

Due to the summer vacation period we are currently understaffed, so delayed replies must be expected. I am sorry about any inconvenience this might cause. Karl is out of office for the time being, so I've been assigned this case in his absence.

Can you provide a sniffer trace of the connection and data transmission so we can get a clearer picture of these timings. The timestamps from your iOS log shows when they were received on the iOS device, and not necessarily when they were transmitted from the nRF52. If you don't have a dedicated sniffer, you can use an nRF52 DK and the nRF Sniffer tool with Wireshark to do a sniffer trace of the connection.

For all I know this delay might come from the iOS handling the data as well. Do you see this when connecting using I.E. an Android phone as well, and the same amount and length of delays?

Best regards,

Simon
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel