Latency measurement (nvds_measure_buffer_latency) gave weird results

Please provide complete information as applicable to your setup.

• Hardware Platform (Jetson / GPU): Jetson AGX Xavier
• DeepStream Version: 5.0
• JetPack Version (valid for Jetson only): 4.4.1
• TensorRT Version: 7.1.3
• Issue Type( questions, new requirements, bugs): question
• How to reproduce the issue ? (This is for bugs. Including which sample app is using, the configuration files content, the command line used and other details for reproducing)

I have a custom pipeline that look like this:

[camera source source-bin 0] \                                             --> queue --> app_sink
                              \                                           /
                                --> streammuxer -> PGIE -> Tracker -> Tee --> queue -->  tiler --> osd --> [...] --> udp_sink
                              /                                           \                       
[camera source source-bin 1] /                                             --> queue --> msgconv --> msgbroker

Use the code here Enable Latency measurement for deepstream sample apps to add latency measurement to my pipeline:

typedef struct {
  GMutex *lock;
  int num_sources;
} LatencyCtx;

static GstPadProbeReturn
latency_measurement_buf_prob(GstPad *pad, GstPadProbeInfo *info, gpointer u_data)
{
  LatencyCtx *ctx = (LatencyCtx *)u_data;
  static int batch_num = 0;
  guint i = 0, num_sources_in_batch = 0;
  if (nvds_enable_latency_measurement)
  {
    GstBuffer *buf = (GstBuffer *)info->data;
    NvDsFrameLatencyInfo *latency_info = NULL;
    g_mutex_lock(ctx->lock);
    latency_info = (NvDsFrameLatencyInfo *) calloc(1, ctx->num_sources * sizeof(NvDsFrameLatencyInfo));
    g_print("\n************BATCH-NUM = %d**************\n", batch_num);
    num_sources_in_batch = nvds_measure_buffer_latency(buf, latency_info);

    for (i = 0; i < num_sources_in_batch; i++)
    {
      g_print("Source id = %d Frame_num = %d Frame latency = %lf (ms) \n",
              latency_info[i].source_id,
              latency_info[i].frame_num,
              latency_info[i].latency);
    }
    g_mutex_unlock(ctx->lock);
    batch_num++;
  }

  return GST_PAD_PROBE_OK;
}

[main function]

test_pad = gst_element_get_static_pad(<element>, "sink");
  if (!test_pad)
  {
    g_print("Unable to get sink pad\n");
  }
  else
  {
    LatencyCtx *latency_ctx = (LatencyCtx *)g_malloc0(sizeof(LatencyCtx));
    latency_ctx->lock = (GMutex *)g_malloc0(sizeof(GMutex));
    latency_ctx->num_sources = NUM_SOURCES;
    gst_pad_add_probe(test_pad, GST_PAD_PROBE_TYPE_BUFFER, latency_measurement_buf_prob, latency_ctx, NULL);
  }
  gst_object_unref(test_pad);

[main function]
  • If <element> is app_sink:
************BATCH-NUM = 5**************
Comp name = stream_muxer in_system_timestamp = 1607707499472.683105 out_system_timestamp = 1607707499525.270996               component latency= 52.587891
Comp name = stream_muxer in_system_timestamp = 1607707499472.512939 out_system_timestamp = 1607707499525.270996               component latency= 52.758057
Comp name = primary-nvinference-engine in_system_timestamp = 1607707499525.291992 out_system_timestamp = 1607707499553.311035               component latency= 28.019043
Comp name = tracker in_system_timestamp = 1607707499553.326904 out_system_timestamp = 1607707499602.200928               component latency= 48.874023
Comp name = nvtiler in_system_timestamp = 1607707499602.334961 out_system_timestamp = 0.000000               component latency= -1607707499602.334961

We have weird value like -1607707499602.334961

  • If <element> is udp_sink:
************BATCH-NUM = 0**************
Batch meta not found for buffer 0x7ec41f2280
  • If <element> is msgbroker:
************BATCH-NUM = 0**************
Comp name = stream_muxer in_system_timestamp = 1607707850898.555908 out_system_timestamp = 1607707850910.142090               component latency= 11.586182
Comp name = stream_muxer in_system_timestamp = 1607707850900.982910 out_system_timestamp = 1607707850910.142090               component latency= 9.159180
Comp name = primary-nvinference-engine in_system_timestamp = 1607707850910.233887 out_system_timestamp = 1607707850990.382080               component latency= 80.148193
Comp name = tracker in_system_timestamp = 1607707850990.418945 out_system_timestamp = 1607707851408.416992               component latency= 417.998047
Comp name = nvtiler in_system_timestamp = 1607707851408.538086 out_system_timestamp = 0.000000               component latency= -1607707851408.538086

************BATCH-NUM = 1**************
Comp name = stream_muxer in_system_timestamp = 1607707850927.357910 out_system_timestamp = 1607707850937.496094               component latency= 10.138184
Comp name = stream_muxer in_system_timestamp = 1607707850935.074951 out_system_timestamp = 1607707850937.497070               component latency= 2.422119
Comp name = primary-nvinference-engine in_system_timestamp = 1607707850937.539062 out_system_timestamp = 1607707851061.644043               component latency= 124.104980
Comp name = tracker in_system_timestamp = 1607707851061.662109 out_system_timestamp = 1607707851415.853027               component latency= 354.190918

Again weird value like -1607707851408.538086, sometime the nvtiler is included, sometime nvtiler is exccuded.

In all cases, no report on the total latency time of the frame for each source is reported. I also observe wildly different component latency depending on whose element’s pad I attached the probe to. I’m not sure what I did wrong?

There is no update from you for a period, assuming this is not an issue any more.
Hence we are closing this topic. If need further support, please open a new one.
Thanks

Can this happens with deepstream-app?