initial commit; added latseq files to repository; added latseq flag to Cmake and build_oai

CMakeLists.txt

@@ -513,6 +513,11 @@ add_boolean_option(ENABLE_USE_CPU_EXECUTION_TIME False "Add data in vcd traces:
 add_boolean_option(ENABLE_VCD              False  "always true now, time measurements of proc calls and var displays" ON)
 add_boolean_option(ENABLE_VCD_FIFO         False  "time measurements of proc calls and var displays sent to FIFO (one more thread)" ON)
 
+##########################
+# PRECISE LATENCY MEASUREMENT LATSEQ options
+##########################
+add_boolean_option(LATSEQ                  False "Activate Latency Sequence tool (LatSeq)" ON)
+
 ##########################
 # PHY options
 ##########################
@@ -633,6 +638,7 @@ add_library(UTIL
   ${OPENAIR_DIR}/common/utils/system.c
   ${OPENAIR_DIR}/common/utils/time_meas.c
   ${OPENAIR_DIR}/common/utils/time_stat.c
+  ${OPENAIR_DIR}/common/utils/LATSEQ/latseq.c
 )
 target_link_libraries(UTIL PUBLIC ${T_LIB} pthread)
 

cmake_targets/build_oai

@@ -158,6 +158,8 @@ Options:
   Enable the memory sanitizer on all targets. Requires clang, and is
   incompatible with ASan/UBSan. To build, issue:
   CC=/usr/bin/clang CXX=/usr/bin/clang++ ./build_oai ... --sanitize-memory
+--enable-latseq
+  enables Latency Sequence tool, https://github.com/Orange-OpenSource/LatSeq
 -h | --help
    Print this help"
 }
@@ -414,6 +416,10 @@ function main() {
        --trace-asn1c-enc-dec)
             CMAKE_CMD="$CMAKE_CMD -DTRACE_ASN1C_ENC_DEC=ON"
             echo_info "Enabling asn1c internal traces via OAI logging system"
+            shift;;
+       --enable-latseq)
+            CMAKE_CMD="$CMAKE_CMD -DLATSEQ=ON"
+            echo_info "Enabling Latency Sequence measurement, https://github.com/Orange-OpenSource/LatSeq"
             shift 1;;
         -h | --help)
             print_help

common/utils/LATSEQ/README

+# LATency SEQuence analysis extension for OpenAirInterface
+
+A tool for internal latency analysis in Base Station.
+Code licenced under BSD-3. See more on https://github.com/Orange-OpenSource/LatSeq
+Author : Flavien Ronteix--Jacquet (Orange Innovation), Alexandre Ferrieux (Orange Innovation)
+Email : flavien.ronteixjacquet@orange.com, alexandre.ferrieux@orange.com
+## Installation
+
+- Put LatSeq extension source code in OAI code (https://gitlab.eurecom.fr/oai/openairinterface5g). We recommend to put it in the path common/utils/LATSEQ.
+- In cmake_targets/CMakeLists.txt put `add_boolean_option(LATSEQ True "Active Latency Sequence tools")`. Also add Latseq to compiled source `set(UTIL_SRC... ${OPENAIR_DIR}/common/utils/LATSEQ/latseq.c`
+- Put test/ in targets/TEST/LATSEQ/
+- Verify installation of LatSeq with `make` in targets/TEST/LATSEQ
+
+## Usage
+
+0) Add init_latseq(appname) and close_latseq() in main Base Station thread at the start and end.
+1) Add a new LatSeq measure point in the code with
+#include "common/utils/LATSEQ/latseq.h"
+#if LATSEQ
+LATSEQ_P("D pdcp--rlc", "pdcp%d.rlc%d", 0, 1);  
+#endif
+
+where first argument is the direction, the second the observed segment and the third argument is a string of data_identifier
+1) Compile OAI code with cmake option LATSEQ at True
+2) Run scanario for Uplink and Downlink
+3) Process lseq traces to yield data do statistics with LatSeq tools
+
+More in docs/Latseq.pdf
+
+## LatSeq measurement module
+
+For now, latseq is designed to be the more independant as possible : Means that it does not use oai LOG system (not register by logInit()) and the flag "LATSEQ" disable all lines related to latseq in the code (using #ifdef). In a second time, it could be conceivable to integrate more deeply latseq into oai code.
+
+latseq_t, global structure for latseq embodied the latseq logging info. log_buffer is a circular buffer with 2 head index, i_write_head and i_read_head. this buffer of latseq_element_t is designed to bo mutex-less.
+
+LATSEQ_P macro calls log_measure(). The idea is to have a low-footprint at logging explains why log_measure() should do a minimal amount of operations.
+
+latseq_log_to_file() is the function run in the logger thread. It writes log_elements in the log file.
+
+LATSEQ_P with direction of D (Downlink) or U (Uplink) observed the passage of a data.
+LATSEQ_P with direction of I (Information) observed a scalar property at a point of code. e.g. buffer occupancy.
+
+**We assume that**:
+- All the point and latseq module run on the same machine (to don't have to synchronize clock of different machines)
+- Clock give by asm rdtsc is same for all the CPU cores (constant_tsc enabled)
+
+### TODO
+
+- [ ] "gtp.in--pdcp.in.gtp" and "ip.in--gtp.in" has been deleted since "gtpv1u_eNB.c" and "NwGtpv1u.c" has been deleted
+
+## TOOLS
+
+Get scripts on https://github.com/Orange-OpenSource/LatSeq/tools
+
+- latseq_checker : verify constitency of Latseq points before compiling
+- latseq_logs : convert lseq log file into useful json file for statistics and visualization
+- latseq_filter : filter output of latseq_logs
+- latseq_stats : perform statistic
+
+### latseq_checker
+Checker to verify that points LATSEQ_P points are consistent.
+Verify the number of argument, the emptiness, format...
+
+ex. ./latseq_checker.sh /home/oai/
+
+### rdtsctots
+convert rdtsc value to unix timestamp value
+
+ex. `./rdtsctots.py trace_raw.lseq > trace.lseq`
+
+### latseq_logs
+Proceeds LatSeq logs.
+A *.lseq is required.
+By default, builds the latseq_log object.
+- Reads lseq file given in raw_input
+- Cleans raw_input to inputs.
+- Builds points structure and paths possible.
+- Saves object related to the *.lseq files to a *.plk (pickle)
+
+**Arguments**:
+- "-h" : help
+- "-C" : cleans pickle file associated to the log file and rebuild
+- "-l" : required lseq file of fingerprints
+- "-i" : request cleaned input measurements in the case of command line script
+- "-r" returns the paths present in the log file as json.
+```
+{
+    "D": [
+        ["ip", "pdcp.in",...],
+        ...
+    ],
+    "U": ...
+}
+``̀
+
+- "-p" returns points structure as json.
+Becareful, if journeys has not been rebuilt, then you do not have "duration" attibute which is used for statistics.
+```
+{
+    "layer1.point": {
+        "next": [layer2.point2,...],
+        "count": 5,
+        "dir": [0],
+        "duration": {
+            "journeys uid": 0.0115,
+            ...
+        }
+    }
+}
+{
+    ...
+}
+```
+
+- "-j" returns journeys structure as json.
+	- Rebuilds journeys with rebuild_packets_journey method
+	- Builds out_journeys
+```
+{
+    "uid": 52,
+    "dir": 0,
+    "glob": {
+        "rnti": "54614",...
+    },
+    "set": [[1542, 1592409314.253678, "rlc.rx.am--pdcp.rx"],[...],...],  # set of pointer to input entry
+    "set_ids": {
+        "drb": "1",...
+    },
+    "path": 0,  # path according to direction and paths obtainable by -p
+    "completed": true,
+    "ts_in": 123.456,
+    "ts_out": 789.012
+}
+{
+    ...
+}
+```
+
+- "-m" returns metadata of information as list
+```
+20200423_143226.191801  rlc.am.txbuf    occ1:drb1
+20200423_143226.191802  rlc.am.txbuf    occ2:drb1
+...
+20200423_143226.192000  rlc.um.txbuf    occ15:drb2
+```
+
+- "-o" returns a latseq journey file line by line. redirects output to a file to have a *.lseqj for waterfall generation
+```
+#funcId ip pdcp.in pdcp.tx rlc.tx.um rlc.seg.um mac.mux mac.txreq phy.out.proc phy.in.proc mac.demux rlc.rx.um rlc.unseg.um pdcp.rx 
+20200423_143226.191801 D (len64)        ip--pdcp.in.gtp uid0.rnti54614.drb1.gsn12
+20200423_143226.191802 D (len64)        pdcp.in--pdcp.tx        uid0.rnti54614.drb1.gsn12.psn10
+20200423_143226.191803 D (len66)        pdcp.tx--rlc.tx.um      uid0.rnti54614.drb1.psn10.lcid3.rsdu0
+```
+
+Requested json are printed in stdout line by line
+Errors, Warnings, Informations are printed in stderr
+
+Example of usage:
+./latseq_logs.py -l ~/latseq.23042020.lseq 2>/dev/null
+./latseq_logs.py -j -l ~/latseq.23042020.lseq 2>/dev/null
+./latseq_logs.py -p -l ~/latseq.23042020.lseq 2>/dev/null
+./latseq_logs.py -o -l ~/latseq.23042020.lseq > 23042020.lseqj 2>/dev/null
+
+### latseq_filter
+Applies a filter to a json stream.
+It uses jq filters.
+Help website to design jq filter : https://jqplay.org/
+
+Takes a file with a filter or a filter as string in argument.
+
+Example of usage:
+./latseq_filter.sh journeys_downlinks_gsn.lfilter
+cat journeys_downlinks_gsn.lfilter
+> select(.["dir"] == 0 and .["set_ids"]["gsn"] == "18")
+
+### latseq_stats
+Performs statistics from json. Report json or print in stdout.
+
+By default, reads on stdin. "-l" *.lseq will try to open a *.json associated.
+By default, returns a json report on stdout.
+
+Arguments:
+- "-f" enables to choose format "json", "csv",...
+- "-P" prints statistics formated by the latseq_stats module.
+- "-sj" returns statistics on journeys
+`̀``
+{
+    "D": {
+        "size": 34,
+        "min": 0.19598,
+        "max": 1.187086,
+        "mean": 0.788976,
+        "stdev": 0.153623,
+        "quantiles": [0.694859, 0.699043, 0.834942, 0.838041, 0.955701]
+}
+`̀``
+
+- "-sjpp" returns the shares of delay introduced by each point for each journeys by path.
+```
+{
+  "U02": {  # Uplinks, path 0, point 2
+    "size": 4,
+    "min": 0,
+    "max": 0.7273,
+    "mean": 0.36239999999999994,
+    "stdev": 0.2915949673776967,
+    "quantiles": [
+      0.025005000000000003,
+      0.125025,
+      0.36114999999999997,
+      0.598525,
+      0.7015449999999999
+    ]
+  }
+}
+```
+
+- "-sp" returns statistics on points
+```
+{
+    "pdcp.rx": {
+        "dir": "U",
+        "size": 4,
+        "min": 0.01,
+        "max": 0.02,
+        "mean": 0.015,
+        "stdev": 0.005,
+        "quantiles": [0.012,...]  # 5%, 25%, 50%, 75%, 95%
+    },
+    ...
+}
+`̀``
+
+- "-djd" returns data journeys' duration
+`̀``
+{
+    "00": {  # first decimal indicates uplink/downlink followed by the journey unique id
+        "ts": 1587645146.191801,
+        "durations": 0.19598  # in ms
+    },
+    ...
+}
+`̀``
+
+Example of usage of the full toolchain for LatSeq Analysis Module
+./latseq_logs.py -l ~/latseq.simple.lseq -j 2>/dev/null | ./latseq_filter.sh journeys_downlinks_gsn.lfilt | ./latseq_stats.py -sj --print
+
+## TEST_LATSEQ
+in targets/TEST/LATSEQ test_latseq test different part of latseq module
+- "h" : help menu
+- "i" : test init and close latseq
+- "a" : test init, capture 2 fingerprints and close
+- "t" : same test as "a" but with 2 concurrent threads
+- "m" : test measurement time to capture 1000000 fingerprints
+- "n" : test measurement time to capture 1000 fingerprints with 1,2,3,5,10 data identifiers
+- "w" : test writer speed for a simplified data collector
+

common/utils/LATSEQ/latseq.c

+/*
+ * Software Name : LatSeq
+ * Version: 1.0
+ * SPDX-FileCopyrightText: Copyright (c) 2020-2021 Orange Labs
+ * SPDX-License-Identifier: BSD-3-Clause
+ *
+ * This software is distributed under the BSD 3-clause,
+ * the text of which is available at https://opensource.org/licenses/BSD-3-Clause
+ * or see the "license.txt" file for more details.
+ *
+ * Author: Flavien Ronteix--Jacquet
+ * Software description: LatSeq measurement part core
+ */
+
+#define _GNU_SOURCE // required for pthread_setname_np()
+#include "latseq.h"
+
+/*--- GLOBALS and EXTERNS ----------------------------------------------------*/
+
+latseq_t g_latseq;
+__thread latseq_thread_data_t tls_latseq = {
+  .th_latseq_id = 0
+}; // need to be a thread local storage variable.
+pthread_t logger_thread;
+pthread_t fflusher_thread;
+//double cpuf; //cpu frequency in MHz -> usec. Should be initialized in main.c
+extern volatile int oai_exit; //oai is ended. Close latseq
+
+/*--- UTILS FUNCTIONS --------------------------------------------------------*/
+
+uint64_t get_cpu_freq_cycles(void)
+{
+  uint64_t ts = l_rdtsc();
+  sleep(1);
+  return (l_rdtsc() - ts);
+}
+
+/*--- MAIN THREAD FUNCTIONS --------------------------------------------------*/
+
+int init_latseq(const char * appname, uint64_t cpufreq)
+{ 
+  // init members
+  g_latseq.is_running = 0;
+  //synchronise time and rdtsc
+  struct timespec ts;
+  clock_gettime(CLOCK_REALTIME, &ts);
+  g_latseq.time_zero = (uint64_t)ts.tv_sec * 1000000000LL + (uint64_t)ts.tv_nsec;
+  g_latseq.rdtsc_zero = l_rdtsc(); //check at compile time that constant_tsc is enabled in /proc/cpuinfo
+  if (cpufreq == 0) {
+    g_latseq.cpu_freq = get_cpu_freq_cycles();
+  } else {
+    g_latseq.cpu_freq = cpufreq;
+  }
+
+  // Open traces
+  char time_string[16];
+  strftime(time_string, sizeof (time_string), "%d%m%Y_%H%M%S", localtime(&ts.tv_sec));
+  g_latseq.filelog_name = (char *)malloc(LATSEQ_MAX_STR_SIZE);
+  sprintf(g_latseq.filelog_name, "%s.%s.lseq", appname, time_string);
+  //open logfile
+  g_latseq.outstream = fopen(g_latseq.filelog_name, "w");
+  if (g_latseq.outstream == NULL) {
+    g_latseq.is_running = 0;
+    printf("[LATSEQ] Error at opening log file\n");
+    return -1;
+  }
+  //write header
+  char hdr[] = "# LatSeq packet fingerprints\n# By Alexandre Ferrieux and Flavien Ronteix Jacquet\n# timestamp\tU/D\tsrc--dest\tlen:ctxtId:localId\n";
+  size_t ret = fwrite(hdr, sizeof(char), sizeof(hdr) - 1, g_latseq.outstream);
+  if (ret < 0) {
+    printf("[LATSEQ] Error at opening log file\n");
+    g_latseq.is_running = 0;
+    return -1;
+  }
+  fprintf(g_latseq.outstream, "%ld S rdtsc--gettimeofday %ld.%09ld\n", g_latseq.rdtsc_zero, ts.tv_sec, ts.tv_nsec);
+  fflush(g_latseq.outstream);
+  
+  // init registry
+  g_latseq.local_log_buffers.read_ith_thread = 0;
+  g_latseq.local_log_buffers.nb_th = 0;
+  memset(&g_latseq.local_log_buffers.i_read_heads, 0, MAX_NB_THREAD * sizeof(unsigned int));
+  
+  // init stat
+  g_latseq.stats.entry_counter = 0;
+  g_latseq.stats.bytes_counter = 0;
+
+  // init latseq_thread_t
+  tls_latseq.th_latseq_id = 0;
+  
+  // init logger thread
+  g_latseq.is_running = 1;
+  
+  return init_logger_latseq();
+}
+
+int init_logger_latseq(void)
+{
+  // init thread to write buffer to file
+  if(pthread_create(&logger_thread, NULL, (void *) &latseq_log_to_file, NULL) > 0) {
+    printf("[LATSEQ] Error at starting data collector\n");
+    g_latseq.is_running = 0;
+    return -1;
+  }
+  // init thread to flush into file
+  pthread_create(&fflusher_thread, NULL, (void *) &fflush_latseq_periodically, NULL);
+
+  return g_latseq.is_running;
+}
+
+void latseq_print_stats(void)
+{
+  printf("[LATSEQ] === stats ===\n");
+  printf("[LATSEQ] number of entry in log : %d\n", g_latseq.stats.entry_counter);
+  //printf("[LATSEQ] heads positions : %d (Write) : %d (Read)\n", g_latseq.i_write_head, g_latseq.i_read_head);
+}
+
+int close_latseq(void)
+{
+  g_latseq.is_running = 0;
+  //Wait logger finish to write data
+  pthread_join(logger_thread, NULL);
+  //At this point, data_ids and points should be freed by the logger thread
+  free((char*) g_latseq.filelog_name);
+  if (fclose(g_latseq.outstream)){
+    fprintf(stderr, "[LATSEQ] error on closing %s\n", g_latseq.filelog_name);
+    exit(EXIT_FAILURE);
+  }
+  return 1;
+}
+
+/*--- INSTRUMENTED THREAD FUNCTIONS ------------------------------------------*/
+
+int init_thread_for_latseq(void)
+{
+
+  //Init tls_latseq for local thread
+  tls_latseq.i_write_head = 0; //local thread tls_latseq
+  //memset(tls_latseq.log_buffer, 0, sizeof(tls_latseq.log_buffer));
+
+  //Register thread in the registry
+  latseq_registry_t * reg = &g_latseq.local_log_buffers;
+  //Check if space left in registry
+  if (reg->nb_th >= MAX_NB_THREAD) {
+    g_latseq.is_running = 0;
+    fprintf(g_latseq.outstream, "Max instrumented thread MAX_NB_THREAD reached\n");
+    return -1;
+  }
+  reg->tls[reg->nb_th] = &tls_latseq;
+  reg->i_read_heads[reg->nb_th] = 0;
+
+  //Give id to the thread
+  reg->nb_th++;
+  tls_latseq.th_latseq_id = reg->nb_th;
+  return 0;
+  //TODO : No destroy function ? What happens when thread is stopped and data had not been written in the log file ?
+}
+
+/*--- DATA COLLECTOR THREAD FUNCTIONS ----------------------------------------*/
+
+static int write_latseq_entry(void)
+{
+  //reference to latseq_thread_data
+  latseq_thread_data_t * th = g_latseq.local_log_buffers.tls[g_latseq.local_log_buffers.read_ith_thread];
+  //read_head for this thread_data
+  unsigned int * i_read_head = &g_latseq.local_log_buffers.i_read_heads[g_latseq.local_log_buffers.read_ith_thread];
+  //reference to element to write
+  latseq_element_t * e = &th->log_buffer[(*i_read_head)%RING_BUFFER_SIZE];
+
+  char * tmps;
+  //Convert latseq_element to a string
+  tmps = calloc(LATSEQ_MAX_STR_SIZE, sizeof(char));
+  //Write the data identifier, e.g. do the vsprintf() here and not at measure()
+  //We put the first NB_DATA_IDENTIFIERS elements of array, even there are no NB_DATA_IDENTIFIERS element to write. sprintf will get the firsts...
+  sprintf(
+    tmps,
+    e->format, 
+    e->data_id[0],
+    e->data_id[1],
+    e->data_id[2],
+    e->data_id[3],
+    e->data_id[4],
+    e->data_id[5],
+    e->data_id[6],
+    e->data_id[7],
+    e->data_id[8],
+    e->data_id[9]);
+
+  // Write into file
+  int ret = fprintf(g_latseq.outstream, "%ld %s %s\n",
+    e->ts,
+    e->point,
+    tmps);
+
+  if (ret < 0) {
+    g_latseq.is_running = 0;
+    fclose(g_latseq.outstream);
+    fprintf(stderr, "[LATSEQ] output log file cannot be written\n");
+    exit(EXIT_FAILURE);
+  }
+#ifdef LATSEQ_DEBUG
+  fprintf(g_latseq.outstream, "# debug %ld.%06ld : log an entry (len %d) for %s\n", etv.tv_sec, etv.tv_usec, ret, e->point);
+  fprintf(g_latseq.outstream, "# info %ld.%06ld : buffer occupancy (%d / %d) for thread which embedded %s\n",etv.tv_sec, etv.tv_usec, OCCUPANCY((*(&th->i_write_head)%RING_BUFFER_SIZE), ((*i_read_head)%RING_BUFFER_SIZE)), RING_BUFFER_SIZE, e->point);
+#endif
+
+  free(tmps);
+  // cleanup buffer element
+  e->ts = 0;
+  memset(e->data_id, 0, (sizeof(uint32_t) * e->len_id));
+  e->len_id = 0;
+  
+  //Update read_head for the current read_ith_thread
+  //Update g_latseq.local_log_buffers.i_read_heads[g_latseq.local_log_buffers.read_ith_thread] head position
+  (*i_read_head)++;
+
+  return ret;
+}
+
+void latseq_log_to_file(void)
+{
+  // pthread config
+  pthread_t thId = pthread_self();
+  //set name
+  pthread_setname_np(thId, "latseq_log_to_file");
+  //set priority
+  int prio_for_policy = 10;
+  pthread_setschedprio(thId, prio_for_policy);
+
+  latseq_registry_t * reg = &g_latseq.local_log_buffers;
+  int items_to_read = 0;
+
+  while (!oai_exit) { // run until oai is stopped
+    if (!g_latseq.is_running) { break; } //running flag is at 0, not running
+    //If no thread registered, continue and wait
+    if (reg->nb_th == 0) { usleep(1000); continue; }
+    //Select a thread to read with read_ith_thread. 
+    // Using RR for now, WRR in near future according to occupancy
+    if (reg->read_ith_thread + 1 >= reg->nb_th) {
+      reg->read_ith_thread = 0;
+    } else {
+      reg->read_ith_thread++;
+    }
+
+    //If max occupancy reached for a local buffer
+    if (reg->tls[reg->read_ith_thread]->i_write_head < reg->i_read_heads[reg->read_ith_thread]) {
+      fprintf(g_latseq.outstream, "# Error\tring buffer of thread (%d) reach max occupancy of %d\n", reg->read_ith_thread, RING_BUFFER_SIZE);
+    }
+
+    items_to_read = CHUNK_SIZE_ITEMS;
+    // Write by chunk
+    while (reg->tls[reg->read_ith_thread]->i_write_head > reg->i_read_heads[reg->read_ith_thread] && items_to_read > 0 ) {
+      //printf("[debug] th %d : (%d)w (%d)r : (%d)items_to_read\n", reg->read_ith_thread, reg->tls[reg->read_ith_thread]->i_write_head, reg->i_read_heads[reg->read_ith_thread], items_to_read);
+      items_to_read--;
+      //Write pointed entry into log file
+      g_latseq.stats.bytes_counter += (uint32_t)write_latseq_entry();
+      g_latseq.stats.entry_counter++;
+    }
+    usleep(1);
+  } // while(!oai_exit)
+
+  //Write all remaining data
+  for (uint8_t i = 0; i < reg->nb_th; i++) {
+    reg->read_ith_thread = i;
+    while (reg->tls[reg->read_ith_thread]->i_write_head > reg->i_read_heads[reg->read_ith_thread])
+    {
+      g_latseq.stats.bytes_counter += (uint32_t)write_latseq_entry();
+      g_latseq.stats.entry_counter++;
+    }
+  }
+  //close_latseq(); // function to close latseq properly
+  //exit thread
+  pthread_exit(NULL);
+}
+
+void fflush_latseq_periodically(void)
+{
+  struct timespec ts;
+  while(1){
+    sleep(1);
+    fflush(g_latseq.outstream);
+    clock_gettime(CLOCK_REALTIME, &ts);
+    fprintf(g_latseq.outstream, "%ld S rdtsc--gettimeofday %ld.%09ld\n", l_rdtsc(), ts.tv_sec, ts.tv_nsec);
+  }
+  pthread_exit(NULL);
+}

targets/TEST/LATSEQ/Makefile

+#################################################################################
+# Software Name : LatSeq
+# Version: 1.0
+# SPDX-FileCopyrightText: Copyright (c) 2020-2021 Orange Labs
+# SPDX-License-Identifier: BSD-3-Clause
+#
+# This software is distributed under the BSD 3-clause,
+# the text of which is available at https://opensource.org/licenses/BSD-3-Clause
+# or see the "license.txt" file for more details.
+#
+# Author: Flavien Ronteix--Jacquet
+# Software description: tests makefile
+#################################################################################
+
+
+TEST_DIR	= $(shell pwd)
+OPENAIR_DIR 	= $(TEST_DIR)/../../..
+OPENAIR2_COMMON = $(OPENAIR_DIR)/openair2/COMMON
+UTILS_DIR 	= $(OPENAIR_DIR)/common/utils
+LATSEQ_DIR	= $(UTILS_DIR)/LATSEQ
+
+CC = gcc
+
+#CFLAGS += -m32 -DPHYSIM -DNB_ANTENNAS_RX=2 -DNB_ANTENNAS_TX=2 -I/usr/include/X11
+#CFLAGS += -I/usr/include/libxml2 -L/usr/local/lib -I/usr/include/atlas -L/usr/X11R6/lib 
+CFLAGS += -std=gnu99 # to be compiled in c99 like all oai
+CFLAGS += -Wall -Wconversion
+CFLAGS += -g
+#CFLAGS += -pg
+#CFLAGS += -O3
+CFLAGS += -DLATSEQ
+#CFLAGS += -DLATSEQ_DEBUG
+CFLAGS += -DTEST_LATSEQ
+CFLAGS += -I$(OPENAIR_DIR) -I$(OPENAIR2_COMMON) -I$(UTILS_DIR)  -I$(LATSEQ_DIR)
+
+LDLIBS = -lpthread
+
+VPATH += $(LATSEQ_DIR)
+VPATH += $(MEAS_DIR)
+
+EXE = test_latseq
+SRCS = test_latseq.c latseq.c
+OBJS = $(SRCS:.c=.o)
+
+all: $(EXE)
+
+$(EXE): $(OBJS)
+	@echo "Compiling test_latseq"
+	$(CC) $(CFLAGS) -o $@ $(OBJS) $(LDLIBS)
+
+run: $(EXE)
+	@echo "Run test_latseq"
+	./test_latseq a
+
+run-parsing: $(LATSEQ_DIR)/lseq_stats/lseqlogs.py
+	cd $(LATSEQ_DIR)/lseq_stats/;\
+	      	./lseqlogs.py -l $(TEST_DIR)/test1.lseq
+
+clean:
+	rm -f core gmon.out $(EXE) *.o test.*.lseq

targets/TEST/LATSEQ/test_latseq.c

+/*
+ * Software Name : LatSeq
+ * Version: 1.0
+ * SPDX-FileCopyrightText: Copyright (c) 2020-2021 Orange Labs
+ * SPDX-License-Identifier: BSD-3-Clause
+ *
+ * This software is distributed under the BSD 3-clause,
+ * the text of which is available at https://opensource.org/licenses/BSD-3-Clause
+ * or see the "license.txt" file for more details.
+ *
+ * Author: Flavien Ronteix--Jacquet
+ * Software description: LatSeq measurement part core
+ */
+
+/*! \file test_latseq.c
+* \brief latency sequence tool test program
+* \author Flavien Ronteix--Jacquet
+* \date 2020
+* \version 1.0
+* @ingroup util
+*/
+
+#define _GNU_SOURCE
+#include <stdio.h>
+#include <unistd.h>
+#include <pthread.h>
+#include "latseq.h"
+
+double cpuf;
+const char * test_log = "test";
+
+volatile int  oai_exit = 1; //Emulate global variable used by oai to indicate that oai is running
+
+void print_usage(void) 
+{
+  printf("help test_latseq\n");
+  printf("h \t: Help\n");
+  printf("a \t: test_full() \t: a full unit test\n");
+  printf("i \t: test_init_and_close() \t: test a simple init/close case\n");
+  printf("t \t: test_multi_thread() \t: test multi-producers in different thread case\n");
+  printf("m \t: measure_log_measure() \t: measure time took by log_measure\n");
+  printf("n \t: measure_log_n() \t: measure time took by log_measure with n varargs\n");
+  printf("w \t: measure_writer() \t: measure time to write\n");
+}
+
+int test_init_and_close() 
+{
+  oai_exit = 0;
+  printf("[TEST] %s\n",__func__);
+  if(!init_latseq(test_log, 0)) {
+    printf("[ERROR] : init_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+  sleep(1);
+  if(!close_latseq()) {
+    printf("[ERROR] : close_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+
+  return 0;
+}
+
+int test_full() 
+{
+  oai_exit = 0;
+  printf("[TEST] %s\n",__func__);
+  if(!init_latseq(test_log, 0)) {
+    printf("[ERROR] : init_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+  //int num = 1000000;
+  int num = 1;
+  int i;
+  for (i=0; i < num; i++){
+    LATSEQ_P("full3 D", "ip%d", 0);
+    //sleep(1);
+    usleep(1);
+    LATSEQ_P("full2 D", "ip%d.mac%d", 0, 1);
+  }
+  printf("sizeof latseq_element : %ld\n", sizeof(struct latseq_element_t));
+  oai_exit = 1;
+  if(!close_latseq()) {
+    printf("[ERROR] : close_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+  return 0;
+}
+
+void thread_test1(void)
+{
+  pthread_t thId = pthread_self();
+  printf("[TEST] [%ld] thread started\n", thId);
+  int i = 0;
+  while(!oai_exit) {
+    if (!i) {
+      LATSEQ_P("full3 D", "ip%d", 0);
+      usleep(11000);
+      LATSEQ_P("full2 D", "ip%d.mac%d", 0, 1);
+      i = 1;
+      continue;
+    }
+  }
+  pthread_exit(NULL);
+}
+
+void thread_test2(void)
+{
+  pthread_t thId = pthread_self();
+  printf("[TEST] [%ld] thread started\n", thId);
+  int i = 0;
+  while(!oai_exit) {
+    if (!i) {
+      LATSEQ_P("full3 D", "ip%d", 1);
+      usleep(1000);
+      LATSEQ_P("full2 D", "ip%d.mac%d", 1, 1);
+      usleep(9000);
+      LATSEQ_P("full1 D", "ip%d.mac%d.phy%d", 1, 1, 4);
+      i = 1;
+      continue;
+    }
+  }
+  printf("[TEST] [%ld] thread stopped\n", thId);
+  pthread_exit(NULL);
+}
+
+int test_multithread() 
+{
+  oai_exit = 0;
+  printf("[TEST] %s\n",__func__);
+  if(!init_latseq(test_log, 0)) {
+    printf("[ERROR] : init_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+  pthread_t th1;
+  pthread_t th2;
+  pthread_create(&th1, NULL, (void *) &thread_test1, NULL);
+  pthread_create(&th2, NULL, (void *) &thread_test2, NULL);
+  usleep(25000);
+  oai_exit = 1;
+  pthread_join(th1, NULL);
+  pthread_join(th2, NULL);
+
+  if(!close_latseq()) {
+    printf("[ERROR] : close_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+  return 0;
+}
+
+// Repeat experiment 3 times for i in {1..3}; do ./test_latseq m | awk '{print $6}' | sed -r '/^\s*$/d' >> measurement_res.txt; done
+
+int measure_log_measure()
+{
+  oai_exit = 0;
+  printf("[TEST] %s\n",__func__);
+  if(!init_latseq(test_log, 0)) {
+    printf("[ERROR] : init_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+#ifdef TEST_LATSEQ
+  struct timeval begin, end;
+  gettimeofday(&begin, NULL);
+#endif
+  const uint32_t num_call = 1000000;
+  for (int i = 0; i < num_call; i++)
+  {
+    //LATSEQ_P("meas", "call.%d.%d.%d.%d.%d.%d.%d.%d.%d.%d", i,i,i,i,i,i,i,i,i,i);
+    LATSEQ_P("meas", "call.%d.%d.%d.%d.%d.%d.%d", i,i,i,i,i,i,i);
+    //LATSEQ_P("meas", "call.%d.%d.%d.%d.%d", i,i,i,i,i);
+    //LATSEQ_P("meas", "call.%d", i);
+    //usleep(1);
+  }
+
+#ifdef TEST_LATSEQ
+  gettimeofday(&end, NULL);
+#endif
+  oai_exit = 1;
+  //sleep(1);
+  
+  if(!close_latseq()) {
+    printf("[ERROR] : close_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+#ifdef TEST_LATSEQ
+  printf("[LATSEQ] %d log_measure took : %lu us\n", num_call, (end.tv_usec - begin.tv_usec)); //at 23-03, 0.0328usec
+#endif
+
+  return 0;
+}
+
+int measure_log_n() 
+{
+  oai_exit = 0;
+  printf("[TEST] %s\n",__func__);
+  if(!init_latseq(test_log, 0)) {
+    printf("[ERROR] : init_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+  //usleep(10000); //TODO : with this, generate a corrupted size vs. prev_size
+#ifdef TEST_LATSEQ
+  struct timeval begin, end;
+  gettimeofday(&begin, NULL);
+  long t1, t2, t3, t5, t10;
+#endif
+  const uint32_t num_call = 1000;
+  int i;
+  for (i = 0; i < num_call; i++)
+  {
+    LATSEQ_P("meas1", "call.%d", i);
+  }
+#ifdef TEST_LATSEQ
+  gettimeofday(&end, NULL);
+  t1 = end.tv_usec - begin.tv_usec;
+  gettimeofday(&begin, NULL);
+#endif
+  //test n=2
+  for (i = 0; i < num_call; i++)
+  {
+    LATSEQ_P("meas2", "call.%d.%d", i,0);
+  }
+#ifdef TEST_LATSEQ
+  gettimeofday(&end, NULL);
+  t2 = end.tv_usec - begin.tv_usec;
+  gettimeofday(&begin, NULL);
+#endif
+  //test n=3
+  for (i = 0; i < num_call; i++)
+  {
+    LATSEQ_P("meas3", "call.%d.%d.%d", i,0,1);
+  }
+#ifdef TEST_LATSEQ
+  gettimeofday(&end, NULL);
+  t3 = end.tv_usec - begin.tv_usec;
+  gettimeofday(&begin, NULL);
+#endif
+  //test n=5
+  for (i = 0; i < num_call; i++)
+  {
+    LATSEQ_P("meas3", "call.%d.%d.%d.%d.%d", i,0,1,2,3);
+  }
+#ifdef TEST_LATSEQ
+  gettimeofday(&end, NULL);
+  t5 = end.tv_usec - begin.tv_usec;
+  gettimeofday(&begin, NULL);
+#endif
+  //test n=10 (max given by NB_DATA_IDENTIFIERS)
+  for (i = 0; i < num_call; i++)
+  {
+    LATSEQ_P("meas4", "call.%d.%d.%d.%d.%d.%d.%d.%d.%d.%d",i,0,1,2,3,4,5,7,8,9);
+  }
+#ifdef TEST_LATSEQ
+  gettimeofday(&end, NULL);
+  t10 = end.tv_usec - begin.tv_usec;
+#endif
+  oai_exit = 1;
+  sleep(1);
+  
+  if(!close_latseq()) {
+    printf("[ERROR] : close_latseq()\n");
+    exit(EXIT_FAILURE);
+  }
+#ifdef TEST_LATSEQ
+  printf("[LATSEQ] log_measure took :\n"); //at 23-03, 32.8ns
+  printf("\tvar_args=1 : %.1f ns/call\n", 1000*(double)t1/num_call); // mean : 19ns at 23-03
+  printf("\tvar_args=2 : %.1f ns/call\n", 1000*(double)t2/num_call); // mean : 22ns at 23-03
+  printf("\tvar_args=3 : %.1f ns/call\n", 1000*(double)t3/num_call); // mean : 25ns at 23-03
+  printf("\tvar_args=5 : %.1f ns/call\n", 1000*(double)t5/num_call); // mean : 32ns at 23-03
+  printf("\tvar_args=10 : %.1f ns/call\n", 1000*(double)t10/num_call); // mean : 61ns at 23-03
+#endif
+  return 0;
+}
+
+void test_writer(FILE * f, char * tmps, int i)
+{
+  sprintf(tmps, "a%d.b%d", i, i+1);
+  fprintf(f, "%d.%06d %s %s\n", 1, 234567, "D write", tmps);
+}
+
+/*
+ * Compiler avec -pg
+ * résultats au 6-04-2020
+ * %   cumulative   self              self     * total           
+ * time   seconds   seconds    calls  ms/call  ms/call  name    
+ * 71.46      0.05     0.05        1    50.02    70.03  measure_writer
+ * 28.58      0.07     0.02 10000000     0.00     0.00  test_writer
+ */
+int measure_writer()
+{
+  oai_exit = 0;
+  printf("[TEST] %s\n",__func__);
+  FILE * fout = fopen("test1.lseq", "w");
+  //write header
+  char hdr[] = "# LatSeq format\n# By Alexandre Ferrieux and Flavien Ronteix Jacquet\n# timestamp\tU/D\tsrc--dest\tdataId\n#funcId ip.entry sdap.mapping sdap.header pdcp.txbuf pdcp.rohc pdcp.intcipher pdcp.header pdcp.routing rlc.am.txbuf rlc.am.seg rlc.am.header rlc.am.retbuf mac.mux mac.harq.[0-7] phy.crc phy.cbseg phy.msc phy.mod phy.map phy.ant\n";
+  fwrite(hdr, sizeof(char), sizeof(hdr) - 1, fout);
+  const int num_call = 1000000;
+  char * tmps;
+  tmps = calloc(2*10, sizeof(char));
+
+#ifdef TEST_LATSEQ
+  struct timeval begin, end;
+  gettimeofday(&begin, NULL);
+#endif
+  for (int i = 0; i < num_call; i++) {
+    test_writer(fout, tmps, i);
+  }
+#ifdef TEST_LATSEQ
+  gettimeofday(&end, NULL);
+  printf("[LATSEQ] measure_write took : "); //at 23-03, 32.8ns
+  printf("%d writes : %.1ld us\n", num_call, (end.tv_usec - begin.tv_usec));
+#endif
+  fclose(fout);
+  free(tmps);
+  oai_exit = 1;
+  return 0;
+}
+
+int main (int argc, char **argv) 
+{
+  #ifdef LATSEQ
+    printf("[TEST] #ifdef LATSEQ\n");
+  #endif
+  if (argc != 2) {
+    print_usage();
+    exit(-1);
+  }
+  char opt = (char)argv[1][0];
+  switch (opt)
+  {
+  case 'h':
+    print_usage();
+    break;
+
+  case 'i':
+    (void)test_init_and_close();
+    break;
+  
+  case 'a':
+    (void)test_full();
+    break;
+
+  case 't':
+    (void)test_multithread();
+    break;
+  
+  case 'm':
+    (void)measure_log_measure();
+    break;
+
+  case 'n':
+    (void)measure_log_n();
+    break;
+  
+  case 'w':
+    (void)measure_writer();
+    break;
+  
+  default:
+    print_usage();
+    break;
+  }
+  
+  //#endif
+  oai_exit = 1;
+  return 0;
+}