removed unnecessary rlc retransmission points

CMakeLists.txt

@@ -593,6 +593,11 @@ add_boolean_option(ENABLE_USE_CPU_EXECUTION_TIME OFF "Add data in vcd traces: di
 add_boolean_option(ENABLE_VCD              OFF  "always true now, time measurements of proc calls and var displays" ON)
 add_boolean_option(ENABLE_VCD_FIFO         OFF  "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
 ##########################
@@ -680,6 +685,7 @@ set(T_LIB $<TARGET_NAME_IF_EXISTS:T>)
 add_library(UTIL
   ${OPENAIR_DIR}/common/utils/LOG/vcd_signal_dumper.c
   ${OPENAIR2_DIR}/UTIL/OPT/probe.c
+  ${OPENAIR_DIR}/common/utils/LATSEQ/latseq.c
 )
 
 pkg_check_modules(cap libcap)

cmake_targets/build_oai

@@ -136,6 +136,8 @@ Options:
   CC=/usr/bin/clang CXX=/usr/bin/clang++ ./build_oai ... --sanitize-memory
 --sanitize-thread | -fsanitize=thread
   Enable the thread sanitizer on all targets
+--enable-latseq
+  enables Latency Sequence tool, https://github.com/Orange-OpenSource/LatSeq
 -h | --help
    Print this help"
 }
@@ -387,6 +389,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

@@ -0,0 +1,257 @@
+# 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

@@ -0,0 +1,284 @@
+/*
+ * 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);
+}

common/utils/LATSEQ/latseq.h

@@ -0,0 +1,409 @@
+/*
+ * 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
+ */
+
+#ifndef __LATSEQ_H__
+#define __LATSEQ_H__
+
+/*--- INCLUDES ---------------------------------------------------------------*/
+#include <unistd.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <syslog.h>
+#include <assert.h>
+#include <sys/types.h>
+#include <sys/stat.h>
+#include <sys/time.h>
+#include <fcntl.h>
+#include <stdarg.h>
+#include <time.h>
+#include <stdint.h>
+#ifndef __STDC_FORMAT_MACROS
+  #define __STDC_FORMAT_MACROS
+#endif
+#include <inttypes.h>
+#ifndef _GNU_SOURCE
+  #define _GNU_SOURCE
+#endif
+#include <pthread.h>
+#include <utils.h>
+
+/*--- DEFINE -----------------------------------------------------------------*/
+
+#define RING_BUFFER_SIZE    1024 // Number of fingerprints in Ring Buffer
+#define NB_DATA_IDENTIFIERS 10  // to update according to distinct data identifier used in point
+#define LATSEQ_MAX_STR_SIZE 128 // Length for filelog_name AND latseq fingerprint string size
+#define CHUNK_SIZE_ITEMS    16  // Size of chunk of ring buffer to read at data collector. 1 correspoding to full RR, RING_BUFFER_SIZE read all buffer by passage
+#define MAX_NB_THREAD       32  // Maximum number of instrumented threads expected
+
+/*--- MACRO ------------------------------------------------------------------*/
+#define LATSEQ_P3(p, f, i1) do {log_measure1(p, f, (int32_t)i1); } while(0)
+#define LATSEQ_P4(p, f, i1, i2) do {log_measure2(p, f, (int32_t)i1, (int32_t)i2); } while(0)
+#define LATSEQ_P5(p, f, i1, i2, i3) do {log_measure3(p, f, (int32_t)i1, (int32_t)i2, (int32_t)i3); } while(0)
+#define LATSEQ_P6(p, f, i1, i2, i3, i4) do {log_measure4(p, f, (int32_t)i1, (int32_t)i2, (int32_t)i3, (int32_t)i4);} while(0)
+#define LATSEQ_P7(p, f, i1, i2, i3, i4, i5) do {log_measure5(p, f, (int32_t)i1, (int32_t)i2, (int32_t)i3, (int32_t)i4, (int32_t)i5); } while(0)
+#define LATSEQ_P8(p, f, i1, i2, i3, i4, i5, i6) do {log_measure6(p, f, (int32_t)i1, (int32_t)i2, (int32_t)i3, (int32_t)i4, (int32_t)i5, (int32_t)i6); } while(0)
+#define LATSEQ_P9(p, f, i1, i2, i3, i4, i5, i6, i7) do {log_measure7(p, f, (int32_t)i1, (int32_t)i2, (int32_t)i3, (int32_t)i4, (int32_t)i5, (int32_t)i6, (int32_t)i7); } while(0)
+#define LATSEQ_P10(p, f, i1, i2, i3, i4, i5, i6, i7, i8) do {log_measure8(p, f, (int32_t)i1, (int32_t)i2, (int32_t)i3, (int32_t)i4, (int32_t)i5, (int32_t)i6, (int32_t)i7, (int32_t)i8); } while(0)
+#define LATSEQ_P11(p, f, i1, i2, i3, i4, i5, i6, i7, i8, i9) do {log_measure9(p, f, (int32_t)i1, (int32_t)i2, (int32_t)i3, (int32_t)i4, (int32_t)i5, (int32_t)i6, (int32_t)i7, (int32_t)i8, (int32_t)i9); } while(0)
+#define LATSEQ_P12(p, f, i1, i2, i3, i4, i5, i6, i7, i8, i9, i10) do {log_measure10(p, f, (int32_t)i1, (int32_t)i2, (int32_t)i3, (int32_t)i4, (int32_t)i5, (int32_t)i6, (int32_t)i7, (int32_t)i8, (int32_t)i9, (int32_t)i10); } while(0)
+#define GET_MACRO(_1,_2,_3,_4,_5,_6,_7,_8,_9,_10,_11,_12,NAME,...) NAME
+#define LATSEQ_P(...) GET_MACRO(__VA_ARGS__, LATSEQ_P12, LATSEQ_P11, LATSEQ_P10, LATSEQ_P9, LATSEQ_P8, LATSEQ_P7, LATSEQ_P6, LATSEQ_P5, LATSEQ_P4, LATSEQ_P3)(__VA_ARGS__)
+#define OCCUPANCY(w, r) (w - r)
+
+/*--- STRUCT -----------------------------------------------------------------*/
+
+// A latseq element of the buffer
+typedef struct latseq_element_t {
+  uint64_t            ts; // timestamp of the measure
+  const char *        point;
+  const char *        format;
+  ushort              len_id; // Number data identifiers
+  int32_t            data_id[NB_DATA_IDENTIFIERS]; // values for the data identifier. What is the best type ?
+} latseq_element_t;
+
+// Statistics structures for latseq
+typedef struct latseq_stats_t {
+  uint32_t        entry_counter;
+  uint32_t        bytes_counter;
+} latseq_stats_t;
+
+//thread specific data struct
+typedef struct latseq_thread_data_t {
+  uint8_t             th_latseq_id; //Identifier of pthread for registry
+  latseq_element_t    log_buffer[RING_BUFFER_SIZE]; //log buffer, structure mutex-less
+  unsigned int        i_write_head; // position of writer in the log_buffer (main thread)
+} latseq_thread_data_t;
+
+//Registry of pointers to thread-specific struct latseq_data_thread
+typedef struct latseq_registry_t {
+  uint8_t                 read_ith_thread;
+  uint8_t                 nb_th;
+  latseq_thread_data_t *  tls[MAX_NB_THREAD];
+  unsigned int            i_read_heads[MAX_NB_THREAD]; // position of reader in the ith log buffer (logger thread)
+} latseq_registry_t;
+
+// Global structure of LatSeq module
+typedef struct latseq_t {
+  int                 is_running; //1 is running, 0 not running
+  char *              filelog_name;
+  FILE *              outstream; //Output descriptor
+  uint64_t            time_zero; // time zero
+  uint64_t            rdtsc_zero; //rdtsc zero
+  uint64_t            cpu_freq; //cpu frequency
+  latseq_registry_t   local_log_buffers; //Register of thread-specific buffers
+  latseq_stats_t      stats; // stats of latseq instance
+} latseq_t;
+
+/*--- EXTERNS ----------------------------------------------------------------*/
+
+extern latseq_t g_latseq; // global structure
+extern __thread latseq_thread_data_t tls_latseq;
+
+/*--- FUNCTIONS --------------------------------------------------------------*/
+/** \fn int init_latseq(const char * appname);
+ * \brief init latency sequences module.
+ * \param appname app's name. The output file is appname.date_hour.lseq
+ * \param cpufreq. cpu frequency in cycles.
+ * \return -1 if error 1 otherwise
+*/
+int init_latseq(const char * appname, uint64_t cpufreq);
+
+/** \fn init_logger_to_mem(void);
+ * \brief init thread logger
+ * \return -1 if error 1 otherwise
+*/
+int init_logger_latseq(void);
+
+/** \fn init_thread_for_latseq(void);
+ * \brief init tls_latseq for local oai thread
+ * \return -1 if error, 0 otherwise
+*/
+int init_thread_for_latseq(void);
+
+/** \fn l_rdtsc(void);
+ * \brief rdtsc wrapper
+ * \return time
+*/
+static __inline__ uint64_t l_rdtsc(void) {
+  uint32_t a, d;
+  __asm__ volatile ("rdtsc" : "=a" (a), "=d" (d));
+  return (((uint64_t)d)<<32) | ((uint64_t)a);
+}
+
+/** \fn get_cpu_freq_cycles(void);
+ * \brief Compute CPU clock in a 1 second experiment
+ * \return CPU clock in cycles
+*/
+uint64_t get_cpu_freq_cycles(void);
+
+/*--- MEASUREMENTS -----------------------------------------------------------*/
+/** \fn void log_measure(const char * point, const char *identifier);
+ * \brief function to log a new measure into buffer.
+ * From 1 to NB_DATA_IDENTIFIERS
+ * \param point name of the measurement point
+ * \param id identifier for the data pointed
+ * \todo  measure latency introduced by this function
+*/
+static __inline__ void log_measure1(const char * point, const char *fmt, int32_t i1)
+{
+  //check if the oai thread is already registered
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  //get reference on new element
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 1;
+  e->data_id[0] = i1;
+  //Update head position
+  tls_latseq.i_write_head++;
+}
+
+static __inline__ void log_measure2(const char * point, const char *fmt, int32_t i1, int32_t i2)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 2;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  tls_latseq.i_write_head++;
+}
+
+static __inline__ void log_measure3(const char * point, const char *fmt, int32_t i1, int32_t i2, int32_t i3)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 3;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  e->data_id[2] = i3;
+  tls_latseq.i_write_head++;
+}
+
+static __inline__ void log_measure4(const char * point, const char *fmt, int32_t i1, int32_t i2, int32_t i3, int32_t i4)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 4;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  e->data_id[2] = i3;
+  e->data_id[3] = i4;
+  tls_latseq.i_write_head++;
+}
+
+static __inline__ void log_measure5(const char * point, const char *fmt, int32_t i1, int32_t i2, int32_t i3, int32_t i4, int32_t i5)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 5;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  e->data_id[2] = i3;
+  e->data_id[3] = i4;
+  e->data_id[4] = i5;
+  tls_latseq.i_write_head++;
+}
+
+static __inline__ void log_measure6(const char * point, const char *fmt, int32_t i1, int32_t i2, int32_t i3, int32_t i4, int32_t i5, int32_t i6)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 6;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  e->data_id[2] = i3;
+  e->data_id[3] = i4;
+  e->data_id[4] = i5;
+  e->data_id[5] = i6;
+  tls_latseq.i_write_head++;
+}
+
+
+static __inline__ void log_measure7(const char * point, const char *fmt, int32_t i1, int32_t i2, int32_t i3, int32_t i4, int32_t i5, int32_t i6, int32_t i7)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 7;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  e->data_id[2] = i3;
+  e->data_id[3] = i4;
+  e->data_id[4] = i5;
+  e->data_id[5] = i6;
+  e->data_id[6] = i7;
+  tls_latseq.i_write_head++;
+}
+
+
+static __inline__ void log_measure8(const char * point, const char *fmt, int32_t i1, int32_t i2, int32_t i3, int32_t i4, int32_t i5, int32_t i6, int32_t i7, int32_t i8)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 8;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  e->data_id[2] = i3;
+  e->data_id[3] = i4;
+  e->data_id[4] = i5;
+  e->data_id[5] = i6;
+  e->data_id[6] = i7;
+  e->data_id[7] = i8;
+  tls_latseq.i_write_head++;
+}
+
+
+static __inline__ void log_measure9(const char * point, const char *fmt, int32_t i1, int32_t i2, int32_t i3, int32_t i4, int32_t i5, int32_t i6, int32_t i7, int32_t i8, int32_t i9)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 9;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  e->data_id[2] = i3;
+  e->data_id[3] = i4;
+  e->data_id[4] = i5;
+  e->data_id[5] = i6;
+  e->data_id[6] = i7;
+  e->data_id[7] = i8;
+  e->data_id[8] = i9;
+  tls_latseq.i_write_head++;
+}
+
+
+static __inline__ void log_measure10(const char * point, const char *fmt, int32_t i1, int32_t i2, int32_t i3, int32_t i4, int32_t i5, int32_t i6, int32_t i7, int32_t i8, int32_t i9, int32_t i10)
+{
+  if (tls_latseq.th_latseq_id == 0) {
+    //is not initialized yet
+    if (init_thread_for_latseq()) {
+      return;
+    }
+  }
+  latseq_element_t * e = &tls_latseq.log_buffer[tls_latseq.i_write_head%RING_BUFFER_SIZE];
+  e->ts = l_rdtsc();
+  e->point = point;
+  e->format = fmt;
+  e->len_id = 10;
+  e->data_id[0] = i1;
+  e->data_id[1] = i2;
+  e->data_id[2] = i3;
+  e->data_id[3] = i4;
+  e->data_id[4] = i5;
+  e->data_id[5] = i6;
+  e->data_id[6] = i7;
+  e->data_id[7] = i8;
+  e->data_id[8] = i9;
+  e->data_id[9] = i10;
+  tls_latseq.i_write_head++;
+}
+
+/** \fn static int write_latseq_entry(void);
+ * \brief private function to write an entry in the log file
+*/
+//static int write_latseq_entry(void);
+
+/** \fn void log_to_file(void);
+ * \brief function to save buffer of logs into a file
+*/
+void latseq_log_to_file(void);
+
+/** \fn void fflush_latseq_periodically(void);
+ * \brief flush periodically into fprintf
+*/
+void fflush_latseq_periodically(void);
+
+/** \fn void latseq_print_stats(void);
+ * \brief print some stats about latseq
+*/
+void latseq_print_stats(void);
+
+/** \fn int close_latseq(void);
+ * \brief finish latseq measurement if a latseq is running
+ * \return 0 if error 1 otherwise
+*/
+int close_latseq(void);
+
+/*----------------------------------------------------------------------------*/
+
+#endif

downlink.txt

@@ -0,0 +1,42 @@
+DOWNLINK
+
+###############
+#### SDAP #####
+###############
+sdap.pdu--pdcp.hdr
+
+
+###############
+#### PDCP #####
+###############
+pdcp.hdr--pdcp.int_ciph
+pdcp.int_ciph--rlc.buffer
+
+
+###############
+##### RLC #####
+###############
+rlc.buffer--rlc.seg
+rlc.seg--mac.handover
+				rlc.retx--TODO
+
+###############
+##### MAC #####
+###############
+mac.handover--mac.subhdr
+mac.subhdr--mac.dci		mac.subhdr--mac.retx
+				mac.retx--mac.dci
+mac.dci--phy.crc
+
+###############
+##### PHY #####
+###############
+phy.crc--phy.CB_seg
+phy.CB_seg--phy.ldpc
+phy.ldpc--phy.scrambled
+phy.scrambled--phy.modulated
+phy.modulated--phy.re_mapped
+phy.re_mapped--phy.rotated
+phy.rotated--phy.ifft
+phy.ifft--phy.tx_sample_out
+phy.tx_sample_out--phy.out

executables/nr-ru.c

@@ -48,6 +48,7 @@
 
 #include "common/utils/LOG/log.h"
 #include "common/utils/time_manager/time_manager.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 #include <executables/softmodem-common.h>
 /* these variables have to be defined before including ENB_APP/enb_paramdef.h and GNB_APP/gnb_paramdef.h */
@@ -469,6 +470,7 @@ static void rx_rf(RU_t *ru, int *frame, int *slot)
   }
 
   stop_meas(&ru->rx_fhaul);
+  LATSEQ_P("U phy.SOUTHend--phy.fft","::fm%u.sl%u.IQsize%u", *frame, *slot, samples_per_slot*sizeof(c16_t));
 }
 
 static radio_tx_gpio_flag_t get_gpio_flags(RU_t *ru, int slot)
@@ -593,6 +595,7 @@ void tx_rf(RU_t *ru, int frame,int slot, uint64_t timestamp)
                                              siglen + sf_extension,
                                              nt,
                                              flags);
+  LATSEQ_P("D phy.tx_sample_out--phy.out", "::fm%u.sl%u.IQsize%u", frame, slot, (siglen + sf_extension)*sizeof(c16_t));
   LOG_D(PHY,
         "[TXPATH] RU %d tx_rf, writing to TS %lu, %d.%d, unwrapped_frame %d, slot %d, flags %d, siglen+sf_extension %d, "
         "returned %d, E %f\n",
@@ -774,6 +777,8 @@ void ru_tx_func(void *param)
   if (ru->fh_north_asynch_in == NULL && ru->feptx_ofdm)
     ru->feptx_ofdm(ru, frame_tx, slot_tx);
 
+  LATSEQ_P("D phy.ifft--phy.tx_sample_out", "::fm%u.sl%u", frame_tx, slot_tx);
+
   if (ru->fh_north_asynch_in == NULL && ru->fh_south_out)
     ru->fh_south_out(ru, frame_tx, slot_tx, info->timestamp_tx);
   if (ru->fh_north_out)
@@ -940,6 +945,7 @@ void *ru_thread(void *param)
 
     // synchronization on input FH interface, acquire signals/data and block
     LOG_D(PHY,"[RU_thread] read data: frame_rx = %d, tti_rx = %d\n", frame, slot);
+    LATSEQ_P("U phy.SOUTHstart--phy.SOUTHend","::fm%u.sl%u", frame, slot);
 
     AssertFatal(ru->fh_south_in, "No fronthaul interface at south port");
     ru->fh_south_in(ru, &frame, &slot);
@@ -986,6 +992,7 @@ void *ru_thread(void *param)
         break; // nothing to wait for: we have to stop
       if (ru->feprx) {
         ru->feprx(ru,proc->tti_rx);
+        LATSEQ_P("U phy.fft--phy.prach_pucch","::fm%u.sl%u", frame, slot);
         LOG_D(NR_PHY, "Setting %d.%d (%d) to busy\n", proc->frame_rx, proc->tti_rx, proc->tti_rx % RU_RX_SLOT_DEPTH);
         //LOG_M("rxdata.m","rxs",ru->common.rxdata[0],1228800,1,1);
         LOG_D(PHY,"RU proc: frame_rx = %d, tti_rx = %d\n", proc->frame_rx, proc->tti_rx);

executables/nr-softmodem.c

@@ -87,6 +87,7 @@ unsigned short config_frames[4] = {2,9,11,13};
 #include "x2ap_eNB.h"
 #include "openair1/SCHED_NR/sched_nr.h"
 #include "openair2/SDAP/nr_sdap/nr_sdap.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 pthread_cond_t nfapi_sync_cond;
 pthread_mutex_t nfapi_sync_mutex;
@@ -612,6 +613,7 @@ int main( int argc, char **argv ) {
                          : TIME_SOURCE_REALTIME);
 
   // start the main threads
+  init_latseq("/tmp/latseq", (uint64_t)(cpuf*1000000000LL));
   number_of_cards = 1;
 
   wait_gNBs();
@@ -723,6 +725,7 @@ int main( int argc, char **argv ) {
 
   itti_wait_tasks_end(NULL);
   printf("Returned from ITTI signal handler\n");
+  close_latseq(); //close before end of threads
 
   nfapi_stop_l1();
 

openair1/PHY/CODING/nrLDPC_coding/nrLDPC_coding_interface.h

@@ -57,6 +57,7 @@ typedef struct nrLDPC_segment_decoding_parameters_s{
   bool *d_to_be_cleared;
   uint8_t *c;
   bool decodeSuccess;
+  uint8_t decode_iterations;
   time_stats_t ts_deinterleave;
   time_stats_t ts_rate_unmatch;
   time_stats_t ts_ldpc_decode;

openair1/PHY/CODING/nrLDPC_coding/nrLDPC_coding_segment/nrLDPC_coding_segment_decoder.c

@@ -104,6 +104,8 @@ typedef struct nrLDPC_decoding_parameters_s {
   uint8_t *c;
   bool *decodeSuccess;
 
+  uint8_t decode_iterations;
+
   task_ans_t *ans;
 
   time_stats_t *p_ts_deinterleave;
@@ -217,6 +219,8 @@ static void nr_process_decode_segment(void *arg)
   }
   stop_meas(rdata->p_ts_ldpc_decode);
 
+  rdata->decode_iterations = decodeIterations;
+
   // Task completed
   completed_task_ans(rdata->ans);
 }
@@ -299,12 +303,14 @@ int32_t nrLDPC_coding_decoder(nrLDPC_slot_decoding_parameters_t *nrLDPC_slot_dec
   // Execute thread pool tasks
   join_task_ans(t_info.ans);
 
+  int seg_idx = 0;
   for (int pusch_id = 0; pusch_id < nrLDPC_slot_decoding_parameters->nb_TBs; pusch_id++) {
     nrLDPC_TB_decoding_parameters_t *nrLDPC_TB_decoding_parameters = &nrLDPC_slot_decoding_parameters->TBs[pusch_id];
-    for (int r = 0; r < nrLDPC_TB_decoding_parameters->C; r++) {
+    for (int r = 0; r < nrLDPC_TB_decoding_parameters->C; r++, seg_idx++) {
       if (nrLDPC_TB_decoding_parameters->segments[r].decodeSuccess) {
         *nrLDPC_TB_decoding_parameters->processedSegments = *nrLDPC_TB_decoding_parameters->processedSegments + 1;
       }
+      nrLDPC_TB_decoding_parameters->segments[r].decode_iterations = arr[seg_idx].decode_iterations;
     }
   }
   return 0;

openair1/PHY/NR_TRANSPORT/nr_dlsch.c

@@ -40,6 +40,7 @@
 #include "PHY/NR_TRANSPORT/nr_transport_common_proto.h"
 #include "executables/softmodem-common.h"
 #include "SCHED_NR/sched_nr.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 // #define DEBUG_DLSCH
 // #define DEBUG_DLSCH_MAPPING
@@ -622,10 +623,12 @@ static int do_one_dlsch(unsigned char *input_ptr, PHY_VARS_gNB *gNB, NR_gNB_DLSC
     }
 #endif
 
+    LATSEQ_P("D phy.scrambled--phy.modulated", "::sl%u.rnti%u", slot, rel15->rnti);
     stop_meas(dlsch_scrambling_stats);
     /// Modulation
     start_meas(dlsch_modulation_stats);
     nr_modulation(scrambled_output, encoded_length, Qm, (int16_t *)mod_symbs[codeWord]);
+    LATSEQ_P("D phy.modulated--phy.re_mapped", "::sl%u.qm%u.rnti%u.modulatedsize%u", slot, Qm, rel15->rnti, encoded_length);
     stop_meas(dlsch_modulation_stats);
 #ifdef DEBUG_DLSCH
     printf("PDSCH Modulation: Qm %d(%d)\n", Qm, nb_re);
@@ -761,6 +764,7 @@ static int do_one_dlsch(unsigned char *input_ptr, PHY_VARS_gNB *gNB, NR_gNB_DLSC
     }
     stop_meas(&gNB->dlsch_precoding_stats);
   }
+  LATSEQ_P("D phy.re_mapped--phy.rotated", "::sl%u.nbanttx%u.rnti%u.nbsymbols%u", slot, frame_parms->nb_antennas_tx, rel15->rnti, rel15->NrOfSymbols+1);
   stop_meas(&gNB->dlsch_pdsch_generation_stats);
   /* output and its parts for each dlsch should be aligned on 64 bytes (or 8 * 64 bits)
    * should remain a multiple of 8 * 64 with enough offset to fit each dlsch
@@ -840,6 +844,7 @@ void nr_generate_pdsch(PHY_VARS_gNB *gNB, int n_dlsch, NR_gNB_DLSCH_t *dlsch_arr
       == -1) {
     return;
   }
+  LATSEQ_P("D phy.ldpc--phy.scrambled", "::fm%u.sl%u", frame, slot);
   stop_meas(dlsch_encoding_stats);
 
   unsigned char *output_ptr = output;

openair1/PHY/NR_TRANSPORT/nr_dlsch_coding.c

@@ -36,6 +36,7 @@
 #include "common/utils/nr/nr_common.h"
 #include <syscall.h>
 #include <openair2/UTIL/OPT/opt.h>
+#include "common/utils/LATSEQ/latseq.h"
 
 // #define DEBUG_DLSCH_CODING
 // #define DEBUG_DLSCH_FREE 1
@@ -178,6 +179,7 @@ int nr_dlsch_encoding(PHY_VARS_gNB *gNB,
       AssertFatal((A / 8) + 3 <= max_bytes, "A %d is too big (A/8+3 = %d > %d)\n", A, (A / 8) + 3, max_bytes);
       memcpy(dlsch->b, a, (A / 8) + 3); // using 3 bytes to mimic the case of 24 bit crc
     }
+    LATSEQ_P("D phy.crc--phy.CB_seg", "::fm%u.sl%u.rnti%u", frame, slot, rel15->rnti);
 
     nrLDPC_TB_encoding_parameters_t *TB_parameters = &TBs[i];
 
@@ -194,6 +196,7 @@ int nr_dlsch_encoding(PHY_VARS_gNB *gNB,
                                         &TB_parameters->Z,
                                         &TB_parameters->F,
                                         TB_parameters->BG);
+    LATSEQ_P("D phy.CB_seg--phy.ldpc", "::fm%u.sl%u.nbseg%u.CBbits%u.Fbits%u.rnti%u", frame, slot, TB_parameters->C, TB_parameters->K, TB_parameters->F, rel15->rnti);
     stop_meas(dlsch_segmentation_stats);
 
     if (TB_parameters->C > MAX_NUM_NR_DLSCH_SEGMENTS_PER_LAYER * rel15->nrOfLayers) {

openair1/PHY/NR_TRANSPORT/nr_ulsch_decoding.c

@@ -40,6 +40,7 @@
 #include <syscall.h>
 // #define DEBUG_ULSCH_DECODING
 // #define gNB_DEBUG_TRACE
+#include "common/utils/LATSEQ/latseq.h"
 
 #define OAI_UL_LDPC_MAX_NUM_LLR 27000 // 26112 // NR_LDPC_NCOL_BG1*NR_LDPC_ZMAX = 68*384
 // #define DEBUG_CRC
@@ -289,14 +290,22 @@ int nr_ulsch_decoding(PHY_VARS_gNB *phy_vars_gNB,
     uint32_t offset = 0;
     for (int r = 0; r < TB_parameters.C; r++) {
       nrLDPC_segment_decoding_parameters_t nrLDPC_segment_decoding_parameters = TB_parameters.segments[r];
+      int decode_iter = nrLDPC_segment_decoding_parameters.decode_iterations;
       // Copy c to b in case of decoding success
       if (nrLDPC_segment_decoding_parameters.decodeSuccess) {
         memcpy(harq_process->b + offset,
                harq_process->c[r],
                (harq_process->K >> 3) - (harq_process->F >> 3) - ((harq_process->C > 1) ? 3 : 0));
+        LATSEQ_P("U phy.CB_dec--phy.TB_dec","::fm%u.sl%u.hqpid%u.segment%u.rnti%u.iter%u", ulsch->frame, nr_tti_rx, ulsch->harq_pid, r, ulsch->rnti, decode_iter);
       } else {
         LOG_D(PHY, "uplink segment error %d/%d\n", r, harq_process->C);
         LOG_D(PHY, "ULSCH %d in error\n", ULSCH_id);
+        if (harq_process->round == 3) {
+          LATSEQ_P("U phy.CB_dec--phy.retx_drop","::fm%u.sl%u.hqpid%u.segment%u.nbsegments%u.rnti%u.hqround%u.iter%u", ulsch->frame, nr_tti_rx, ulsch->harq_pid, r, TB_parameters.C, ulsch->rnti, harq_process->round, decode_iter);
+        } else {
+          LATSEQ_P("U phy.CB_dec--phy.dec_fail","::fm%u.sl%u.hqpid%u.segment%u.nbsegments%u.rnti%u.hqround%u.iter%u", ulsch->frame, nr_tti_rx, ulsch->harq_pid, r, TB_parameters.C, ulsch->rnti, harq_process->round, decode_iter);
+          LATSEQ_P("U phy.dec_fail--phy.prach_pucch","::fm%u.sl%u.hqpid%u.rnti%u", ulsch->frame, nr_tti_rx, ulsch->harq_pid, ulsch->rnti);
+        }
       }
       offset += ((harq_process->K >> 3) - (harq_process->F >> 3) - ((harq_process->C > 1) ? 3 : 0));
 

openair1/PHY/NR_TRANSPORT/nr_ulsch_demodulation.c

@@ -14,6 +14,7 @@
 #include "T.h"
 #include <sys/time.h>
 #include "PHY/log_tools.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 
 #if T_TRACER
@@ -1161,6 +1162,7 @@ int nr_rx_pusch_tp(PHY_VARS_gNB *gNB,
   //------------------- Channel estimation -------------------
   //----------------------------------------------------------
   start_meas(&gNB->ulsch_channel_estimation_stats);
+  LATSEQ_P("U phy.prach_pucch--phy.CH_est", "::fm%u.sl%u.hqpid%u.rnti%u.mcs%u.qammod%u.hqround%u", frame, slot, harq_pid, rel15_ul->rnti, rel15_ul->mcs_index, rel15_ul->qam_mod_order, gNB->ulsch[ulsch_id].harq_process->round);
   int max_ch = 0;
   uint32_t nvar = 0;
   int end_symbol = rel15_ul->start_symbol_index + rel15_ul->nr_of_symbols;
@@ -1243,6 +1245,7 @@ int nr_rx_pusch_tp(PHY_VARS_gNB *gNB,
                              rel15_ul->ul_dmrs_symb_pos,
                              rel15_ul->rb_size);
 
+  LATSEQ_P("U phy.CH_est--phy.demodulated", "::fm%u.sl%u.hqpid%u.nbantrx%u.rnti%u.nblayers%u.nbsymbols%u", frame, slot, harq_pid, frame_parms->nb_antennas_rx, rel15_ul->rnti, rel15_ul->nrOfLayers, rel15_ul->nr_of_symbols+1);
   stop_meas(&gNB->ulsch_channel_estimation_stats);
 
   start_meas(&gNB->rx_pusch_init_stats);
@@ -1603,6 +1606,7 @@ int nr_rx_pusch_tp(PHY_VARS_gNB *gNB,
 #endif
 
   join_task_ans(&ans);
+  LATSEQ_P("U phy.demodulated--phy.CB_dec", "::fm%u.sl%u.hqpid%u.rnti%u.nbsymbols%u", frame, slot, harq_pid, rel15_ul->rnti, rel15_ul->nr_of_symbols+1);
   stop_meas(&gNB->rx_pusch_symbol_processing_stats);
 
   // Copy the data to the scope. This cannot be performed in one call to gNBscopeCopy because the data is not contiguous in the

openair1/SCHED_NR/phy_procedures_nr_gNB.c

@@ -40,6 +40,7 @@
 #include <stdint.h>
 #include <openair1/PHY/TOOLS/phy_scope_interface.h>
 #include "PHY/log_tools.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 //#define DEBUG_RXDATA
 //#define SRS_IND_DEBUG
@@ -312,6 +313,7 @@ void phy_procedures_gNB_TX(PHY_VARS_gNB *gNB,
  
   if (num_pdsch > 0) {
     LOG_D(PHY, "PDSCH generation started (%d) in frame %d.%d\n", num_pdsch, frame, slot);
+    LATSEQ_P("D mac.dci--phy.crc", "::fm%u.sl%u", frame, slot);
     nr_generate_pdsch(gNB, num_pdsch, gNB->dlsch, frame, slot);
   }
 
@@ -337,6 +339,7 @@ void phy_procedures_gNB_TX(PHY_VARS_gNB *gNB,
     }
   }
   stop_meas(&gNB->phase_comp_stats);
+  LATSEQ_P("D phy.rotated--phy.ifft", "::fm%u.sl%u", frame, slot);
 }
 
 static int nr_ulsch_procedures(PHY_VARS_gNB *gNB, int frame_rx, int slot_rx, bool *ulsch_to_decode, NR_UL_IND_t *UL_INFO)
@@ -511,6 +514,7 @@ static int nr_ulsch_procedures(PHY_VARS_gNB *gNB, int frame_rx, int slot_rx, boo
             ulsch_harq->TBS,
             ulsch->max_ldpc_iterations);
       nr_fill_indication(gNB, ulsch->frame, ulsch->slot, ULSCH_id, ulsch->harq_pid, 0, 0, crc, pdu);
+      LATSEQ_P("U phy.TB_dec--phy.srs", "::fm%u.sl%u.hqpid%u.hqround%u.rnti%u.CBbits%u.Fbits%u.TBS%u.nbsegments%u", ulsch->frame, ulsch->slot, ulsch->harq_pid, ulsch_harq->round, pusch_pdu->rnti, ulsch_harq->K, ulsch_harq->F, ulsch_harq->TBS, ulsch_harq->C);
       LOG_D(PHY, "ULSCH received ok \n");
       ulsch->active = false;
       ulsch_harq->round = 0;
@@ -1362,6 +1366,7 @@ int phy_procedures_gNB_uespec_RX(PHY_VARS_gNB *gNB, int frame_rx, int slot_rx, N
     stop_meas(&gNB->rx_srs_stats);
   }
 
+  LATSEQ_P("U phy.srs--phy.rach_uci", "::fm%u.sl%u", frame_rx, slot_rx);
   stop_meas(&gNB->phy_proc_rx);
 
   if (pucch_decode_done || pusch_decode_done) {

openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_dlsch.c

@@ -43,6 +43,9 @@
 #include "executables/softmodem-common.h"
 #include "../../../nfapi/oai_integration/vendor_ext.h"
 
+#include "common/utils/LATSEQ/latseq.h"
+
+
 ////////////////////////////////////////////////////////
 /////* DLSCH MAC PDU generation (6.1.2 TS 38.321) */////
 ////////////////////////////////////////////////////////
@@ -1239,6 +1242,7 @@ void post_process_dlsch(gNB_MAC_INST *nr_mac, post_process_pdsch_t *pdsch, NR_UE
     /* we do not have to do anything, since we do not require to get data
      * from RLC or encode MAC CEs. The TX_req structure is filled below
      * or copy data to FAPI structures */
+    LATSEQ_P("D mac.retx--mac.dci", "::fm%u.sl%u.hqpid%u.hqround%u", frame, slot, current_harq_pid, harq->round);
     LOG_D(NR_MAC,
           "%d.%2d DL retransmission RNTI %04x HARQ PID %d round %d NDI %d\n",
           frame,
@@ -1315,6 +1319,7 @@ void post_process_dlsch(gNB_MAC_INST *nr_mac, post_process_pdsch_t *pdsch, NR_UE
                 lcid,
                 ndata,
                 bufEnd-buf-sizeof(NR_MAC_SUBHEADER_LONG));
+          LATSEQ_P("D mac.handover--mac.subhdr", "::RMbuf%u.fm%u.sl%u.fmretx%u.slretx%u.hqpid%u.rnti%u.DL_BLER%%%d.nbRBs%u", (char *)buf+sizeof(NR_MAC_SUBHEADER_LONG), frame, slot, frame, slot, current_harq_pid, rnti, (int32_t)(sched_ctrl->dl_bler_stats.bler * 100), sched_pdsch->rbSize);
 
           if (len == 0)
             break;
@@ -1328,6 +1333,8 @@ void post_process_dlsch(gNB_MAC_INST *nr_mac, post_process_pdsch_t *pdsch, NR_UE
           dlsch_total_bytes += len;
           lcid_bytes += len;
           sdus += 1;
+          LATSEQ_P("D mac.subhdr--mac.dci", "::RMbuf%u.fm%u.sl%u.hqpid%u.hqround%u.mcs%u.TBS%u.rnti%u.macpdusize%u", buf-len, frame, slot, current_harq_pid, harq->round, sched_pdsch->mcs, sched_pdsch->tb_size, rnti, len+sizeof(NR_MAC_SUBHEADER_LONG));
+          LATSEQ_P("D mac.subhdr--mac.retx", "::fmretx%u.slretx%u.RMbuf%u.hqpid%u.mcs%u.TBS%u.rnti%u.macpdusize%u", frame, slot, buf-len, current_harq_pid, sched_pdsch->mcs, sched_pdsch->tb_size, rnti, len+sizeof(NR_MAC_SUBHEADER_LONG));
         }
 
         UE->mac_stats.dl.lc_bytes[lcid] += lcid_bytes;

openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c

@@ -35,6 +35,7 @@
 #include "utils.h"
 #include <openair2/UTIL/OPT/opt.h>
 #include "LAYER2/nr_rlc/nr_rlc_oai_api.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 //#define SRS_IND_DEBUG
 
@@ -498,7 +499,7 @@ static int nr_process_mac_pdu(instance_t module_idP,
           LOG_I(NR_MAC, "RNTI %04x LCID %d: ignoring %d bytes\n", UE->rnti, lcid, mac_len);
         } else {
           UE->mac_stats.ul.lc_bytes[lcid] += mac_len;
-
+          LATSEQ_P("U mac.demuxed--rlc.dec", "::fm%u.sl%u.hqpid%u.MRbuf%u.macsdusize%u.UEbuffer%d.10xSNR%u.UL_BLER%%%d.UE_RSRP%d.nbPRBs%d", frameP, slot, harq_pid, pduP+mac_subheader_len, mac_len, sched_ctrl->estimated_ul_buffer, sched_ctrl->pusch_snrx10, (int32_t)(sched_ctrl->ul_bler_stats.bler * 100), sched_ctrl->CSI_report.ssb_rsrp_report.r[0].RSRP, UE->mac_stats.NPRB);
           nr_mac_rlc_data_ind(module_idP, UE->rnti, true, lcid, (char *)(pduP + mac_subheader_len), mac_len);
 
           sdus += 1;

openair2/LAYER2/nr_pdcp/nr_pdcp_entity.c

@@ -32,6 +32,7 @@
 #include "nr_pdcp_sdu.h"
 
 #include "LOG/log.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 /**
  * @brief returns the maximum PDCP PDU size
@@ -95,6 +96,7 @@ static void nr_pdcp_entity_recv_pdu(nr_pdcp_entity_t *entity,
     header_size = LONG_PDCP_HEADER_SIZE;
   }
   entity->stats.rxpdu_sn = rcvd_sn;
+  LATSEQ_P("U pdcp.hdr_dec--pdcp.int_ciph_dec", "::sn%u.PSbuf%u.pdcppdusize%u.pdusessionid%u", rcvd_sn, buffer, size, entity->rb_id);
 
   /* SRBs always have MAC-I, even if integrity is not active */
   if (entity->has_integrity || entity->type == NR_PDCP_SRB) {
@@ -154,12 +156,14 @@ static void nr_pdcp_entity_recv_pdu(nr_pdcp_entity_t *entity,
       return;
     }
   }
+  LATSEQ_P("U pdcp.int_ciph_dec--pdcp.deliver", "::sn%u.pdusessionid%u", rcvd_sn, entity->rb_id);
 
   if (rcvd_count < entity->rx_deliv
       || nr_pdcp_sdu_in_list(entity->rx_list, rcvd_count)) {
     LOG_W(PDCP, "discard NR PDU rcvd_count=%d, entity->rx_deliv %d,sdu_in_list %d\n", rcvd_count,entity->rx_deliv,nr_pdcp_sdu_in_list(entity->rx_list,rcvd_count));
     entity->stats.rxpdu_dd_pkts++;
     entity->stats.rxpdu_dd_bytes += size;
+    LATSEQ_P("U pdcp.deliver--pdcp.discard_rcvdsmallerdeliv", "::sn%u.pdcpsdusize%u.pdusessionid%u", rcvd_sn, size-header_size-integrity_size, entity->rb_id);
 
     return;
   }
@@ -182,6 +186,7 @@ static void nr_pdcp_entity_recv_pdu(nr_pdcp_entity_t *entity,
     uint32_t count = entity->rx_deliv;
     while (entity->rx_list != NULL && count == entity->rx_list->count) {
       nr_pdcp_sdu_t *cur = entity->rx_list;
+      LATSEQ_P("U pdcp.deliver--sdap.sdu", "::sn%u.PSbuf%u.pdcpsdusize%u.pdusessionid%u", cur->count, cur->buffer, sdu->size, entity->rb_id);
       entity->deliver_sdu(entity->deliver_sdu_data, entity,
                           cur->buffer, cur->size,
                           &cur->msg_integrity);
@@ -264,6 +269,7 @@ static int nr_pdcp_entity_process_sdu(nr_pdcp_entity_t *entity,
     buf[2] = sn & 0xff;
     header_size = LONG_PDCP_HEADER_SIZE;
   }
+  LATSEQ_P("D pdcp.hdr--pdcp.int_ciph", "::SPbuf%u.sn%u.Pbuf%u.pdusessionid%u", buffer, sn, buf, entity->rb_id);
 
   /* SRBs always have MAC-I, even if integrity is not active */
   if (entity->has_integrity || entity->type == NR_PDCP_SRB) {
@@ -300,6 +306,7 @@ static int nr_pdcp_entity_process_sdu(nr_pdcp_entity_t *entity,
   entity->stats.txpdu_bytes += header_size + size + integrity_size;
   entity->stats.txpdu_sn = sn;
 
+  LATSEQ_P("D pdcp.int_ciph--rlc.buffer", "::sn%u.Pbuf%u.pdusessionid%u.pdcppdusize%u", sn, buf, entity->rb_id, header_size + size + integrity_size);
   return header_size + size + integrity_size;
 }
 
@@ -419,6 +426,8 @@ static void check_t_reordering(nr_pdcp_entity_t *entity)
   /* deliver all SDUs with count < rx_reord */
   while (entity->rx_list != NULL && entity->rx_list->count < entity->rx_reord) {
     nr_pdcp_sdu_t *cur = entity->rx_list;
+    LATSEQ_P("U pdcp.deliver--pdcp.deliver_ooo", "::sn%u.pdcpsdusize%u.pdusessionid%u", cur->count, cur->size, entity->rb_id);
+    LATSEQ_P("U pdcp.deliver_ooo--sdap.sdu", "::sn%u.PSbuf%u.pdusessionid%u", cur->count, cur->buffer, entity->rb_id);
     entity->deliver_sdu(entity->deliver_sdu_data, entity,
                         cur->buffer, cur->size,
                         &cur->msg_integrity);
@@ -433,6 +442,8 @@ static void check_t_reordering(nr_pdcp_entity_t *entity)
   count = entity->rx_reord;
   while (entity->rx_list != NULL && count == entity->rx_list->count) {
     nr_pdcp_sdu_t *cur = entity->rx_list;
+    LATSEQ_P("U pdcp.deliver--pdcp.deliver_reorder", "::sn%u.pdcpsdusize%u.pdusessionid%u", cur->count, cur->size, entity->rb_id);
+    LATSEQ_P("U pdcp.deliver_reorder--sdap.sdu", "::sn%u.PSbuf%u.pdusessionid%u", cur->count, cur->buffer, entity->rb_id);
     entity->deliver_sdu(entity->deliver_sdu_data, entity,
                         cur->buffer, cur->size,
                         &cur->msg_integrity);

openair2/LAYER2/nr_pdcp/nr_pdcp_oai_api.c

@@ -61,6 +61,7 @@
 #include "pdcp_messages_types.h"
 #include "openair2/LAYER2/nr_rlc/nr_rlc_oai_api.h"
 #include "utils.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 #define TODO do { \
     printf("%s:%d:%s: todo\n", __FILE__, __LINE__, __FUNCTION__); \

openair2/LAYER2/nr_rlc/nr_rlc_entity_am.c

@@ -29,6 +29,7 @@
 #include "LOG/log.h"
 #include "common/utils/time_stat.h"
 #include "common/utils/assertions.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 /* for a given SDU/SDU segment, computes the corresponding PDU header size */
 static int compute_pdu_header_size(nr_rlc_entity_am_t *entity,
@@ -222,6 +223,7 @@ static void reassemble_and_deliver(nr_rlc_entity_am_t *entity, int sn)
     return;
 
   /* deliver */
+  LATSEQ_P("U rlc.reassembled--pdcp.hdr_dec", "::sn%u.rlcpacketsize%u", sn, so);
   entity->common.deliver_sdu(entity->common.deliver_sdu_data,
                              (nr_rlc_entity_t *)entity,
                              sdu, so);
@@ -349,6 +351,7 @@ static void process_control_pdu(nr_rlc_entity_am_t *entity,
   }
   ack_sn = nr_rlc_pdu_decoder_get_bits(&decoder, entity->sn_field_length); R(decoder);
   e1 = nr_rlc_pdu_decoder_get_bits(&decoder, 1); R(decoder);
+
   /* r bits */
   if (entity->sn_field_length == 18) {
     nr_rlc_pdu_decoder_get_bits(&decoder, 1); R(decoder);
@@ -405,6 +408,7 @@ static void process_control_pdu(nr_rlc_entity_am_t *entity,
       /* check that current nack is > previous nack and <= ack
        * if not then reject the control PDU
        */
+      LATSEQ_P("D rlc.nack--rlc.retx", "::sn%u.so%u.so_end%d", cur_nack_sn, cur_so_start, cur_so_end);
       if (prev_nack_sn != -1) {
         cmp = sn_compare_tx(entity, cur_nack_sn, prev_nack_sn);
         if (cmp < 0
@@ -803,6 +807,7 @@ void nr_rlc_entity_am_recv_pdu(nr_rlc_entity_t *_entity,
   }
 
   data_size = size - decoder.byte;
+  LATSEQ_P("U rlc.dec--rlc.reassembled", "::MRbuf%u.si%u.sn%u.so%u.rlcsegsize%u", buffer, si, sn, so, data_size);
 
   /* dicard PDU if no data */
   if (data_size <= 0) {
@@ -1657,6 +1662,7 @@ static int generate_retx_pdu(nr_rlc_entity_am_t *entity, char *buffer,
   entity->common.stats.txpdu_retx_pkts++;
   entity->common.stats.txpdu_retx_bytes += ret_size;
 
+  LATSEQ_P("D rlc.retx--mac.handover", "::sn%u.sdu_size%u.req_size%u.so%u.RMbuf%u.poll%u.Rbuf%u.retx_count%d.ref_count%d", sdu->sdu->sn, sdu->size, size, sdu->so, buffer, p, sdu, sdu->sdu->retx_count, sdu->sdu->ref_count);
   return ret_size;
 //  return serialize_sdu(entity, sdu, buffer, size, p);
 }
@@ -1697,12 +1703,6 @@ static int generate_tx_pdu(nr_rlc_entity_am_t *entity, char *buffer, int size)
   /* update buffer status */
   entity->common.bstatus.tx_size -= pdu_size;
 
-  /* assign SN to SDU */
-  if (sdu->sdu->sn == -1) {
-    sdu->sdu->sn = entity->tx_next;
-    entity->tx_next = (entity->tx_next + 1) % entity->sn_modulus;
-  }
-
   /* segment if necessary */
   if (pdu_size > size) {
     LOG_D(RLC, "Segmentation (header %d + data %d) / (%d)\n", pdu_header_size, size - pdu_header_size, pdu_size - pdu_header_size);
@@ -1750,6 +1750,9 @@ static int generate_tx_pdu(nr_rlc_entity_am_t *entity, char *buffer, int size)
     entity->force_poll = 0;
   }
   int ret_size = serialize_sdu(entity, sdu, buffer, size, p);
+  LATSEQ_P("D rlc.seg--mac.handover", "::rlcsegsize%u.Rbuf%u.sn%u.so%u.RMbuf%u.poll%u", ret_size, sdu->sdu, sdu->sdu->sn, sdu->so, buffer, p);
+  LATSEQ_P("D rlc.seg--rlc.tpoll_exp", "::Rbuf%u.sn%u.so%u.poll%u", sdu->sdu, sdu->sdu->sn, sdu->so, p);
+  LATSEQ_P("D rlc.seg--rlc.nack", "::Rbuf%u.sn%u.so%u.poll%u", sdu->sdu, sdu->sdu->sn, sdu->so, p);
 
   entity->common.stats.txpdu_pkts++;
   entity->common.stats.txpdu_bytes += ret_size;
@@ -1852,16 +1855,22 @@ void nr_rlc_entity_am_recv_sdu(nr_rlc_entity_t *_entity,
 
   sdu = nr_rlc_new_sdu(buffer, size, sdu_id);
 
+  /* assign SN to SDU, should move this into function nr_rlc_new_sdu()*/
+  sdu->sdu->sn = entity->tx_next;
+  entity->tx_next = (entity->tx_next + 1) % entity->sn_modulus;
+
   LOG_D(RLC, "Created new RLC SDU and append it to the RLC list \n");
 
   nr_rlc_sdu_segment_list_append(&entity->tx_list, &entity->tx_end, sdu);
 
   /* update buffer status */
-  entity->common.bstatus.tx_size += compute_pdu_header_size(entity, sdu)
-                                    + sdu->size;
+  int complete_size = compute_pdu_header_size(entity, sdu) + sdu->size;
+  entity->common.bstatus.tx_size += complete_size;
 
   if (entity->common.avg_time_is_on)
     sdu->sdu->time_of_arrival = time_average_now();
+
+  LATSEQ_P("D rlc.buffer--rlc.seg", "::PRbuf%u.Rbuf%u.sn%u.dl_bs%u.rlcsize%u", buffer, sdu->sdu, sdu->sdu->sn, entity->common.bstatus.tx_size, complete_size);
 }
 
 /*************************************************************************/
@@ -1939,6 +1948,7 @@ static void check_t_poll_retransmit(nr_rlc_entity_am_t *entity)
           cur->sdu->sn, cur->so, cur->size, cur->sdu->retx_count);
 
     /* put in retransmit list */
+    LATSEQ_P("D rlc.tpoll_exp--rlc.retx", "::sn%u.sdu_size%u.so%u", cur->sdu->sn, cur->size, cur->so);
     entity->retransmit_list = nr_rlc_tx_sdu_segment_list_add(entity,
                                   entity->retransmit_list, cur);
 

openair2/NR_PHY_INTERFACE/NR_IF_Module.c

@@ -44,6 +44,7 @@
 #include "openair2/PHY_INTERFACE/queue_t.h"
 #include "utils.h"
 #include "nfapi/oai_integration/nfapi_pnf.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 #define MAX_IF_MODULES 100
 
@@ -453,6 +454,7 @@ static void NR_UL_indication(NR_UL_IND_t *UL_info)
   if (UL_info->rach_ind.number_of_pdus > 0)
     handle_nr_rach(UL_info);
   handle_nr_uci(UL_info);
+  LATSEQ_P("U phy.rach_uci--mac.demuxed", "::fm%u.sl%u", UL_info->frame, UL_info->slot);
   handle_nr_ulsch(UL_info);
   handle_nr_srs(UL_info);
 

openair2/SDAP/nr_sdap/nr_sdap_entity.c

@@ -33,6 +33,7 @@
 #include "rlc.h"
 #include "tuntap_if.h"
 #include "nr_sdap.h"
+#include "common/utils/LATSEQ/latseq.h"
 
 #define NO_SDAP_HEADER 0
 
@@ -90,6 +91,7 @@ static bool nr_sdap_tx_entity(nr_sdap_entity_t *entity,
                               const uint32_t *destinationL2Id,
                               const uint8_t qfi,
                               const bool rqi) {
+  LATSEQ_P("D sdap.pdu--pdcp.hdr", "::sdappdusize%u.SPbuf%u.ueid%u.pdusessionid%u", sdu_buffer_size, sdu_buffer, entity->ue_id, entity->pdusession_id);
   /* The offset of the SDAP header, it might be 0 if has_sdap_tx is not true in the pdcp entity. */
   int offset=0;
   bool ret = false;
@@ -252,6 +254,7 @@ static void nr_sdap_rx_entity(nr_sdap_entity_t *entity,
     // very very dirty hack gloabl var N3GTPUInst
     instance_t inst = *N3GTPUInst;
     gtpv1uSendDirect(inst, ue_id, pdusession_id, gtp_buf, gtp_len, false, false);
+    LATSEQ_P("U sdap.sdu--gtp.out", "::sdapsdusize%u.ueid%u.pdusessionid%u.PSbuf%u", gtp_len, ue_id, pdusession_id, buf);
   } else { //nrUE
     /*
      * TS 37.324 5.2 Data transfer

targets/TEST/LATSEQ/Makefile

@@ -0,0 +1,60 @@
+#################################################################################
+# 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

@@ -0,0 +1,365 @@
+/*
+ * 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;
+}

uplink.txt

@@ -0,0 +1,101 @@
+UPLINK
+
+###############
+#### SDAP #####
+###############
+sdap.sdu--gtp.out
+
+
+###############
+#### PDCP #####
+###############
+pdcp.int_ciph_dec--sdap.sdu	    pdcp.deliver_ooo--sdap.sdu		pdcp.deliver_reorder--sdap.sdu
+				        pdcp.deliver--pdcp.deliver_ooo		pdcp.deliver--pdcp.deliver_reorder
+										
+										pdcp.int_ciph_dec--pdcp.discarded_rcvdsmallerdeliv
+
+pdcp.int_ciph_dec--pdpc.deliver
+
+pdcp.hdr_dec--pdcp.int_ciph_dec
+
+###############
+##### RLC #####
+###############
+rlc.reassembled--pdcp.hdr_dec
+rlc.dec--rlc.reassembled
+ 
+
+###############
+##### MAC #####
+###############
+mac.demuxed--rlc.dec
+
+
+###############
+##### PHY #####
+###############
+phy.rach_uci--mac.demuxed
+phy.srs--phy.rach_uci
+phy.TB_dec--phy.srs	                phy.dec_fail--phy.prach_pucch
+phy.CB_dec--phy.TB_dec	            phy.CB_dec--phy.dec_fail		    phy.CB_dec--phy.retx_drop
+phy.demodulated--phy.CB_dec
+phy.CH_est--phy.demodulated
+phy.prach_pucch--phy.CH_est
+phy.fft--phy.prach_pucch
+phy.SOUTHend--phy.fft
+phy.SOUTHstart--phy.SOUTHend
+
+
+
+
+################
+##### Flow #####
+################
+
+rx_func() { // nr-gnb.c
+    phy_procedures_gNB_uspec_rx() { // phy_procedures_nr_gNB.c
+        decode pucch
+        nr_rx_pusch_tp() { // nr_ulsch_demodulation.c
+            LATSEQ_P( U phy.pracch_pucch
+            Ch_estimation()
+            LATSEQ_P( U phy.CH_est
+            extract_rbs()
+            nr_scale_channel()
+            nr_channel_level()
+            nr_pusch_symbol_processing() { // nr_ulsch_demodulation.c
+                inner_rx() { // nr_ulsch_demodulation.c
+                    nr_ulsch_extract_rbs()
+                    nr_ulsch_channel_compensation()
+                    nr_ulsch_compute_ML_llr() or nr_ulsch_mmse_2layers() or nr_ulsch_compute_llr() 
+                }
+            }
+            LATSEQ_P( U phy.demodulated--
+            nr_ulsch_procedures() {  // phy_procedures_nr_gNB.c
+                nr_ulsch_decoding() { // nr_ulsch_decoding.c
+                    LATSEQ_P( U phy.CB_dec--
+                }
+                nr_fill_indication()
+                LATSEQ_P( U phy.TB_dec--
+                many srs procedure functions
+                LATSEQ_P( U phy.srs--
+            }
+        }
+    }
+    
+    NR_UL_indication() pointer on NR_UL_indication() { // NR_IF_Module.c function and pointer
+        handle_nr_uci()
+        LATSEQ_P( U phy.rach_uci--
+        handle_nr_ulsch() { // NR_IF_Module.c
+            nr_rx_sdu() {
+                _nr_rx_sdu() {
+                    nr_process_mac_pdu() {
+                        decode_ul_mac_sub_pdu_header()
+                        LATSEQ_P( U mac.demuxed--
+                        nr_mac_rlc_ind()
+                    }
+                }
+            }
+        }
+    }
+}
+