libevent-timer-precision-1484.cpp

//
// Created by tonyyxliu on 7/11/23.
//
// This is a test for the problem related to the unexpected delay of libevent
// timeout event callback trigger
//
// Compile this program in release mode and link it with two libraries: 'event' and 'glog'
//

#include <iostream>
#include <cassert>
#include <event2/buffer.h>
#include <event2/event.h>
#include <event2/util.h>
#include <glog/logging.h>

unsigned int num_issue_attempts = 0;
unsigned int num_missed_requests = 0;
long request_interval_us = 100;
long test_duration_us = 3'000'000; // 3 second
event_base *m_base = nullptr;
event *m_issue_event = nullptr;
event *m_wrapup_event = nullptr;
timeval next_issue_time{};
timeval next_wrapup_time{};

/**
 * @brief Transfer from timeval struct to double (in seconds)
 * @param tv
 * @return
 */
double timeval_to_double(timeval *tv)
{
    return tv->tv_sec + static_cast<double>(tv->tv_usec) / 1e+06;
}

/**
 * @brief Transfer from double (in seconds) to timeval struct
 * @param time_val
 * @param tv
 * @return
 */
void double_to_timeval(double time_val, timeval *tv)
{
    auto secs = static_cast<long long>(time_val);
    tv->tv_sec = secs;
    tv->tv_usec = static_cast<int>((time_val - secs) * 1e+06);
}

timeval clock_gettime_tv()
{
    timeval now;
    timespec now_ts;
    int err = clock_gettime(CLOCK_MONOTONIC_RAW, &now_ts);
    assert(err == 0);
    TIMESPEC_TO_TIMEVAL(&now, &now_ts);
    return now;
}

/**
 * Add a event for listening and update the next time to tick this event
 * @param timeout_event
 * @param next_tick_time
 * @param tick_interval
 * @return true on success, false on error (timeout later than expected)
 */
void add_timeout_event(event *const timeout_event, timeval &next_tick_time,
                       const long next_tick_interval_us, bool check)
{
    timeval now = clock_gettime_tv();
    timeval time_before_next_tick{}, diff{};

    evutil_timersub(&now, &next_tick_time, &diff);
    if (check)
        assert(diff.tv_sec >= 0 && (diff.tv_usec - next_tick_interval_us) >= 0);

    // Trigger the timeout event immediately if the tick interval is 0
    if (next_tick_interval_us == 0)
    {
        event_active(timeout_event, 0, 0);
        return;
    }
    // Update the next time of tick
    timeval interval = { .tv_sec = 0, .tv_usec = next_tick_interval_us };
    evutil_timeradd(&next_tick_time, &interval, &next_tick_time);
    evutil_timersub(&next_tick_time, &now, &time_before_next_tick);
#ifdef DEBUG
    LOG(INFO) << "tick_interval is " << next_tick_interval_us << " us.";
    LOG(INFO) << "Time before next tick is: " << time_before_next_tick.tv_sec
              << "s and " << time_before_next_tick.tv_usec << "usec.";
#endif
    if (check)
        assert(time_before_next_tick.tv_sec >= 0);
    // No need to delete the event since new timeout will replace the old
    // one
    evtimer_add(timeout_event, &time_before_next_tick);
}

/**
 * Callback function for tick event.
 * It sends the requests with the help of protocol and trigger the tick()
 * function to set another tick timeout event.
 * @param fd: socket
 * @param events: events
 * @param arg: can be transformed to the pointer of Connection class
 */
void timeout_callback(evutil_socket_t fd, short events, void *arg)
{
    num_issue_attempts++;
#ifdef DEBUG
    LOG(INFO) << "Issue_callback function triggered.";
#endif
    // Set timeout event again for the next issue
    add_timeout_event(m_issue_event, next_issue_time, request_interval_us, true);
    // Send requests here
}

/**
 * Callback function for the wrapup event. The timeout is set as the duration
 * of the connection / load generation. When this event is triggered, the
 * connection should be closed and load generation finished.
 * @param fd: socket
 * @param events: events
 * @param arg: can be transformed to the pointer of Connection class
 */
void wrapup_callback(evutil_socket_t fd, short events, void *arg)
{
#ifdef DEBUG
    LOG(INFO) << "Test Wrapup";
#endif
    // Delete timeout events
    evtimer_del(m_issue_event);
    evtimer_del(m_wrapup_event);
    // Stop listening for events
    event_base_loopbreak(m_base);
    // Resource destruction
    event_free(m_issue_event);
    event_free(m_wrapup_event);
    event_base_free(m_base);
    // Statistics logging
    LOG(INFO) << "Number of issue attempts: " << num_issue_attempts;
    LOG(INFO) << "Number of missed requests: " << num_missed_requests;
    LOG(INFO) << "Miss request: "
              << 100.0 * num_missed_requests /
                     (num_missed_requests + num_issue_attempts)
              << "%";
    // Print the version of libevent
    LOG(INFO) << "libevent linked version: " << event_get_version() << "\n";
    LOG(INFO) << "libevent headers version: " << LIBEVENT_VERSION << "\n";
    LOG(INFO) << "libevent version number: " << std::hex
              << LIBEVENT_VERSION_NUMBER << "\n";
}

int main()
{
    event_config *m_event_config = event_config_new();
    event_config_set_flag(m_event_config, EVENT_BASE_FLAG_PRECISE_TIMER|EVENT_BASE_FLAG_NO_CACHE_TIME);

    // Initialize the next time to tick timeout events as the current time,
    // which will be updated in each iteration
    next_issue_time = clock_gettime_tv();
    next_wrapup_time = clock_gettime_tv();

    m_base = event_base_new_with_config(m_event_config);
    m_issue_event = evtimer_new(m_base, timeout_callback, nullptr);
    m_wrapup_event = evtimer_new(m_base, wrapup_callback, nullptr);

    // Activate the timeout events
    add_timeout_event(m_wrapup_event, next_wrapup_time, test_duration_us, false);
    {
        timeval interval = { .tv_sec = 0, .tv_usec = request_interval_us };
        evtimer_add(m_issue_event, &interval);
    }

    // Start listening for events
    event_base_dispatch(m_base);
}