test-multi-thread-logs.cpp

Go to the documentation of this file.

// License: Apache 2.0. See LICENSE file in root directory.
// Copyright(c) 2020 Intel Corporation. All Rights Reserved.

//#cmake:add-file log-common.h
#include "log-common.h"
#include <atomic>


#ifdef EASYLOGGINGPP_ASYNC

std::atomic<int> atomic_integer(0);
std::chrono::milliseconds max_time = (std::chrono::milliseconds)0;
std::chrono::milliseconds min_time = (std::chrono::milliseconds)50;
std::chrono::milliseconds avg_time = (std::chrono::milliseconds)0;
int max_time_iteration = -1;
const int number_of_iterations = 10000;
const int number_of_threads = 10;
std::mutex stats_mutex;
//thresholds
const int checked_log_write_time = 10; //ms
const int required_log_write_time = 50; //ms
const int checked_lag_time = 15; //ms
const int required_lag_time = 50; //ms
//----------------------- HELPER METHODS START -------------------------
// input line example:
//  14/01 16:53:19,866 DEBUG [884] (rs.cpp:2579) atomic integer = 7
int get_time_from_line(std::string line)
{
    auto time_word = line.substr(7, 12);
    auto hours = stoi(time_word.substr(0, 2));
    auto minutes = stoi(time_word.substr(3, 5));
    auto seconds = stoi(time_word.substr(6, 8));
    auto ms = stoi(time_word.substr(9, 12));
    //std::cout << "h:m:s:ms = " << hours << ":" << minutes << ":" << seconds << ":" << ms << std::endl;
    return (ms + seconds * 1000 + minutes * 1000 * 60 + hours * 1000 * 60 * 60);
}


std::string get_last_line(std::ifstream& in)
{
    std::string line;
    for (int i = 0; i < (number_of_iterations * number_of_threads) - 1; ++i)
    {
        getline(in, line);
    }
    return line;
}

// inputs are use as 2 points that define a line:
// first_time_ms, first_value : x1, y1
// second_time_ms, second_value : x2, y2
// value_in_log : y3
// return value will be x3
int get_log_ideal_time(int first_time_ms, int first_value, int second_time_ms, int second_value, int value_in_log)
{
    int ideal_time = value_in_log * (second_time_ms - first_time_ms) / (second_value - first_value) +
        (first_time_ms * (second_value / (second_value - first_value))) - second_time_ms * (first_value / (second_value - first_value));
    
    return ideal_time;
}

std::pair<unsigned int, int> get_next_50_lines_time_val(std::ifstream& ifs)
{
    unsigned int avg_time_ms = -1;
    int avg_value = -1;
    for (int i = 0; i < 50; ++i) {
        std::string line;
        getline(ifs, line);
        avg_time_ms += get_time_from_line(line);
        avg_value += stoi(line.substr(line.find_last_of(" ") + 1));
    }
    avg_time_ms /= 50;
    avg_value /= 50;
    return std::make_pair(avg_time_ms, avg_value);
}

//----------------------- HELPER METHODS END ---------------------------

TEST_CASE("async logger", "[log][async_log]")
{
    size_t n_callbacks = 0;
    auto callback = [&](rs2_log_severity severity, rs2::log_message const& msg)
    {
        ++n_callbacks;
        std::cout << msg.raw();
    };
    
    auto func = [](int required_value) {
        int iterations = 0;
        
        while (iterations < number_of_iterations)
        {
            std::stringstream ss;
            ss << "atomic integer = " << ++atomic_integer;
            auto start_ms = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now().time_since_epoch());
            rs2::log(RS2_LOG_SEVERITY_DEBUG, ss.str().c_str());
            std::chrono::milliseconds ms = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now().time_since_epoch());
            std::chrono::milliseconds delta_ms = ms - start_ms;
            {
                std::lock_guard<std::mutex> lock(stats_mutex);
                if (delta_ms > max_time) max_time = delta_ms;
                if (delta_ms < min_time) min_time = delta_ms;
                avg_time += delta_ms;
            }
            ++iterations;
        }
    };
    const char* log_file_path = ".//multi-thread-logs.log";
    try 
    {
        remove(log_file_path);
    }
    catch (...) {}
    rs2::log_to_file(RS2_LOG_SEVERITY_DEBUG, log_file_path);

    std::vector<std::thread> threads;

    for (int i = 0; i < number_of_threads; ++i)
    {
        threads.push_back(std::thread(func, i + 1));
    }
    
    for (auto&&t : threads)
    {
        if (t.joinable()) t.join();
    }

    std::this_thread::sleep_for(std::chrono::milliseconds(5000));
    std::stringstream ss;
    CAPTURE(max_time);
    CAPTURE(min_time);
    CAPTURE(avg_time);
    // The threshold in the CHECK_NOFAIL statement should be filled when running in "normal PC"
    // The threshold in the REQUIRE statement should be filled when running CI tests (less cores are available there)
    CHECK_NOFAIL(max_time.count() < checked_log_write_time);
    REQUIRE(max_time.count() < required_log_write_time);
    
    // checking logs correctness - that all the integer's values have been logged
    {
        // preparing array of number of iterations * number of threads
        std::array<char, number_of_iterations * number_of_threads> check_table;
        // setting all cells to 0
        memset(&check_table[0], 0, check_table.size());
        // marking cells at the position of each log integer value to 1
        std::ifstream check_file(log_file_path, std::ios::in);
        if (check_file.good())
        {
            std::string line;
            while (std::getline(check_file, line)) 
            {
                auto value_in_log = stoi(line.substr(line.find_last_of(" ")));
                REQUIRE(value_in_log > 0);
                REQUIRE((value_in_log - 1) < (number_of_iterations* number_of_threads));
                check_table.at(value_in_log - 1) = 1;
            }
            // checking that all cells have value 1, which means that all logs have been sent and received
            std::for_each(check_table.cbegin(), check_table.cend(), [](const char c) {
                REQUIRE(c == 1);
                });
            check_file.close();
        }
    }

    // checking logs order in means of logging time
    {
        std::ifstream check_file(log_file_path, std::ios::in);
        int overall_ms = 0;
        int overall_logs = 0;
        if (check_file.good())
        {
            // get data to calculate "ideal" line
            // using average from 50 first logs as one point,
            // and average of 50 last points as second point
            auto first_50_pair = get_next_50_lines_time_val(check_file);
            unsigned int first_50_avg_time_ms = first_50_pair.first;
            int first_50_avg_value = first_50_pair.second;
            
            std::string line;
            // the aim of this loop is to get the file's cursor before the 50 last lines, 
            // considering it is already after the 50 first lines
            for (int i = 0; i < (number_of_iterations * number_of_threads) - 1 - 50 - 50; ++i)
                getline(check_file, line);
            
            auto last_50_pair = get_next_50_lines_time_val(check_file);
            unsigned int last_50_avg_time_ms = last_50_pair.first;
            int last_50_avg_value = last_50_pair.second;

            // clear and return to start of the file
            check_file.clear();
            check_file.seekg(0);

            // go over each line and check that its logging time is not "far away" in means of time than the "ideal" time
            int max_delta = 0;
            while (getline(check_file, line)) 
            {
                auto value_in_log = stoi(line.substr(line.find_last_of(" ")));
                auto log_time_ms = get_time_from_line(line);
                auto log_ideal_time_ms = get_log_ideal_time(first_50_avg_time_ms, first_50_avg_value, last_50_avg_time_ms, last_50_avg_value, value_in_log);
                auto delta = std::abs(log_ideal_time_ms - log_time_ms);
                if (delta > max_delta) max_delta = delta;
            }
            // The threshold in the CHECK_NOFAIL statement should be filled when running in "normal PC"
            // The threshold in the REQUIRE statement should be filled when running CI tests (less cores are available there)
            CHECK_NOFAIL(max_delta < checked_lag_time);
            REQUIRE(max_delta < required_lag_time);
        }
        check_file.close();
    }

    // checking number of logs throughput per ms
    {
        std::ifstream check_file(log_file_path, std::ios::in);
        int overall_ms = 0;
        int overall_logs = 0;
        if (check_file.good())
        {
            std::string line;
            while (std::getline(check_file, line)) 
            {
                auto previous_time = get_time_from_line(line);
                int logs_counter_in_one_ms = 1;
                while (std::getline(check_file, line))
                {
                    auto current_time = get_time_from_line(line);
                    if (current_time != previous_time)
                    {
                        overall_logs += logs_counter_in_one_ms;
                        ++overall_ms;
                        break;
                    }
                    else
                        ++logs_counter_in_one_ms;
                }                
            }
        }
        check_file.close();
        float average_logs_in_one_ms = (float)overall_logs / overall_ms;
        REQUIRE(average_logs_in_one_ms >= 20.0F);
    }    
}
#endif