cwIoPresetSelApp.cpp,cwIo.h/cpp,cwMidiPort.h,cwMidiAlsa.cpp :

Added audio and MIDI latency reporting implementation.

cwIo.cpp

@@ -31,6 +31,7 @@
 #include "cwWebSock.h"
 #include "cwUi.h"
 
+#include "cwVectOps.h"
 
 namespace cw
 {
@@ -165,6 +166,10 @@ namespace cw
       unsigned                      uiMapN;      //
       bool                          uiAsyncFl;
 
+      sample_t                      latency_meas_thresh_db;
+      sample_t                      latency_meas_thresh_lin;
+      bool                          latency_meas_enable_fl;
+      latency_meas_result_t         latency_meas_result;
     } io_t;
   
 
@@ -1070,7 +1075,7 @@ namespace cw
       return true;          
     }
 
-    // Get sample ponters or advance the pointers on the buffer associates with each device.
+    // Get sample pointers or advance the pointers on the buffer associates with each device.
     enum { kAudioGroupGetBuf, kAudioGroupAdvBuf };
     void _audioGroupProcSampleBufs( io_t* p, audioGroup_t* ag, unsigned processTypeId, unsigned inputFl  )
     {
@@ -1100,6 +1105,39 @@ namespace cw
       }
     }
 
+    void _audio_latency_measure( io_t* p, const audio_msg_t& msg )
+    {
+      if( p->latency_meas_enable_fl )
+      {
+        
+        if( msg.iBufChCnt && p->latency_meas_result.audio_in_ts.tv_nsec == 0 )
+        {
+          sample_t rms = vop::rms(msg.iBufArray[0], msg.dspFrameCnt );
+          
+          if( rms > p->latency_meas_thresh_lin  )
+            time::get(p->latency_meas_result.audio_in_ts);
+          
+          if( rms > p->latency_meas_result.audio_in_rms_max )
+            p->latency_meas_result.audio_in_rms_max = rms;
+        }
+        
+        if( msg.oBufChCnt && p->latency_meas_result.audio_out_ts.tv_nsec == 0 )
+        {
+          sample_t rms = vop::rms(msg.oBufArray[0], msg.dspFrameCnt );
+          
+          if( rms > p->latency_meas_thresh_lin  )
+            time::get(p->latency_meas_result.audio_out_ts);
+          
+          if( rms > p->latency_meas_result.audio_out_rms_max )
+            p->latency_meas_result.audio_out_rms_max = rms;
+        }
+        
+        p->latency_meas_enable_fl = p->latency_meas_result.audio_in_ts.tv_nsec == 0 ||
+                                    p->latency_meas_result.audio_out_ts.tv_nsec == 0;
+          
+      }
+    }
+
     // This is the audio processing thread function. Block on the audio group condition var
     // which is triggered when all the devices in the group are ready by _audioGroupNotifyIfReady().    
     bool _audioGroupThreadFunc( void* arg )
@@ -1134,6 +1172,8 @@ namespace cw
           if((rc = _ioCallback( ag->p, ag->asyncFl, &msg)) != kOkRC )
             cwLogError(rc,"Audio app callback failed %i.",ag->asyncFl);
 
+          _audio_latency_measure( ag->p, ag->msg );
+          
           _audioGroupProcSampleBufs( ag->p, ag, kAudioGroupAdvBuf, true );
           _audioGroupProcSampleBufs( ag->p, ag, kAudioGroupAdvBuf, false );
         }
@@ -3753,6 +3793,77 @@ cw::rc_t cw::io::uiSendMsg( handle_t h, const char* msg )
   return rc;
 }
 
+void cw::io::latency_measure_setup(handle_t h)
+{
+  io_t* p = _handleToPtr(h);
+  p->latency_meas_enable_fl                = true;
+  p->latency_meas_thresh_db  = -50;
+  p->latency_meas_thresh_lin = pow(10.0,p->latency_meas_thresh_db/20.0);
+  p->latency_meas_result.note_on_input_ts  = {0};
+  p->latency_meas_result.note_on_output_ts = {0};
+  p->latency_meas_result.audio_in_ts       = {0};
+  p->latency_meas_result.audio_out_ts      = {0};
+  p->latency_meas_result.audio_in_rms_max  = 0;
+  p->latency_meas_result.audio_out_rms_max = 0;
+
+  if( p->midiH.isValid() )
+    latency_measure_setup(p->midiH);  
+}
+
+cw::io::latency_meas_result_t cw::io::latency_measure_result(handle_t h)
+{
+  io_t* p = _handleToPtr(h);
+
+  if( p->midiH.isValid() )
+  {
+    midi::device::latency_meas_result_t r = latency_measure_result(p->midiH);
+
+    p->latency_meas_result.note_on_input_ts  = r.note_on_input_ts;
+    p->latency_meas_result.note_on_output_ts = r.note_on_output_ts;
+  }
+  
+  return p->latency_meas_result;
+}
+
+void cw::io::latency_measure_report(handle_t h)
+{
+  io_t* p = _handleToPtr(h);  
+  latency_meas_result_t r = latency_measure_result(h);
+  unsigned t0,t1;
+
+  if( r.note_on_input_ts.tv_nsec )
+  {
+    if( r.note_on_output_ts.tv_nsec )
+    {
+      t0 = time::elapsedMicros(r.note_on_input_ts,r.note_on_output_ts);
+      printf("midi in  - midi out:  %6i\n",t0);
+    }
+
+    if( r.audio_in_ts.tv_nsec )
+    {
+      t0 = time::elapsedMicros(r.note_on_output_ts,r.audio_in_ts);
+      t1 = time::elapsedMicros(r.note_on_input_ts,r.audio_in_ts);
+      printf("midi out - audio in:  %6i %6i\n",t0,t1);
+    }
+
+    if( r.audio_out_ts.tv_nsec )
+    {
+      t0 = time::elapsedMicros(r.audio_in_ts,r.audio_out_ts);
+      t1 = time::elapsedMicros(r.note_on_input_ts,r.audio_out_ts);
+      printf("audio in - audio out: %6i %6i\n",t0,t1);
+    }
+
+  }
+
+  printf("Thresh: %f %f db\n",p->latency_meas_thresh_db,p->latency_meas_thresh_lin);
+  if( r.audio_in_rms_max != 0 )
+    printf("audio in max:%f %f dB\n", r.audio_in_rms_max, 20.0*log10(r.audio_in_rms_max));
+  
+  if( r.audio_out_rms_max != 0 )
+    printf("audio out max:%f %f dB\n", r.audio_out_rms_max, 20.0*log10(r.audio_out_rms_max));
+  
+}
+
 
 void cw::io::uiReport( handle_t h )
 {

cwIo.h

@@ -406,6 +406,21 @@ namespace cw
 
     rc_t uiSendMsg( handle_t h, const char* msg );
 
+
+    typedef struct
+    {
+      time::spec_t note_on_input_ts;
+      time::spec_t note_on_output_ts;
+      time::spec_t audio_in_ts;
+      time::spec_t audio_out_ts;
+      sample_t     audio_in_rms_max;
+      sample_t     audio_out_rms_max;
+    } latency_meas_result_t;
+      
+    void latency_measure_setup(handle_t h);
+    latency_meas_result_t latency_measure_result(handle_t h);
+    void latency_measure_report(handle_t h);
+    
     void uiRealTimeReport( handle_t h );
     void uiReport( handle_t h );
     

cwIoPresetSelApp.cpp

@@ -49,6 +49,7 @@ namespace cw
       kIoReportBtnId,
       kNetPrintBtnId,
       kReportBtnId,
+      kLatencyBtnId,
       
       kStartBtnId,
       kStopBtnId,
@@ -148,6 +149,7 @@ namespace cw
       { kPanelDivId,     kIoReportBtnId,  "ioReportBtnId" },
       { kPanelDivId,     kNetPrintBtnId,  "netPrintBtnId" },
       { kPanelDivId,     kReportBtnId,    "reportBtnId" },
+      { kPanelDivId,     kLatencyBtnId,   "latencyBtnId" },
         
       { kPanelDivId,     kStartBtnId,        "startBtnId" },
       { kPanelDivId,     kStopBtnId,         "stopBtnId" },
@@ -1118,9 +1120,9 @@ namespace cw
 
       if( msg.u.midi != nullptr )
       {        
-        
         const io::midi_msg_t& m   = *msg.u.midi;
         const midi::packet_t* pkt = m.pkt;
+        
         // for each midi msg
         for(unsigned j = 0; j<pkt->msgCnt; ++j)
         {
@@ -1131,8 +1133,8 @@ namespace cw
           }
           else                  // this is a triple
           {
-            midi::msg_t* mm = pkt->msgArray + j;
             time::spec_t timestamp;
+            midi::msg_t* mm = pkt->msgArray + j;
             unsigned     id = app->enableRecordFl ? last_store_index(app->mrpH) : kInvalidId;
             unsigned     loc = app->beg_play_loc;
             
@@ -1346,9 +1348,6 @@ namespace cw
             evt_cnt = midi_record_play::event_count(app->mrpH);
           
         io::uiSendValue( app->ioH, uiFindElementUuId(app->ioH,kCurMidiEvtCntId), evt_cnt  );
-      
-        
-
       }
       
     errLabel:
@@ -2986,6 +2985,11 @@ namespace cw
           preset_sel::report_presets(app->psH);
           break;
 
+        case kLatencyBtnId:
+          latency_measure_report(app->ioH);
+          latency_measure_setup(app->ioH);
+          break;
+
         case kSaveBtnId:
           _on_ui_save(app);
           break;

cwMidiAlsa.cpp

@@ -55,6 +55,11 @@ namespace cw
         unsigned         prvTimeMicroSecs; // time of last recognized event in microseconds
         unsigned         eventCnt;         // count of recognized events
         time::spec_t     baseTimeStamp;
+
+        bool                  latency_meas_enable_in_fl;
+        bool                  latency_meas_enable_out_fl;
+        latency_meas_result_t latency_meas_result;
+        
       } device_t;
 
 #define _cmMpErrMsg( rc,  alsaRc, str )       cwLogError(kOpFailRC,"%s : ALSA Error:%i %s",(str),(alsaRc),snd_strerror(alsaRc))
@@ -104,35 +109,34 @@ namespace cw
         *d1 = v & 0x7f;
       }
 
-      rc_t _cmMpPoll(device_t* p)
+      rc_t _handle_alsa_device( device_t* p )
       {
         rc_t rc = kOkRC;
-        int  timeOutMs = 50;
         
         snd_seq_event_t *ev;
         
-        if (poll(p->alsa_fd, p->alsa_fdCnt, timeOutMs) > 0) 
-        {
-          int rc = 1;
 
         do
         {
-            rc = snd_seq_event_input(p->h,&ev);
+            int alsa_rc = snd_seq_event_input(p->h,&ev);
 
             // if no input
-            if( rc == -EAGAIN )
+            if( alsa_rc == -EAGAIN )
             {
               // TODO: report or at least count error
               break;
             }
             
             // if input buffer overrun
-            if( rc == -ENOSPC )
+            if( alsa_rc == -ENOSPC )
             {
               // TODO: report or at least count error
               break;
             }
 
+            // TODO: Improve performance of _cmMpClientIdToDev() and _cmMpInPortIdToPort().
+            // They currently use linear searchs!
+            
             // get the device this event arrived from
             if( p->prvRcvDev==NULL || p->prvRcvDev->clientId != ev->source.client )
               p->prvRcvDev = _cmMpClientIdToDev(p,ev->source.client);
@@ -163,6 +167,15 @@ namespace cw
                 status = kNoteOnMdId;
                 d0     = ev->data.note.note;
                 d1     = ev->data.note.velocity;
+
+                if( p->latency_meas_enable_in_fl )
+                {
+                  p->latency_meas_enable_in_fl = false;
+                  time::get(p->latency_meas_result.note_on_input_ts);
+                  //p->latency_meas_result.note_on_input_ts.tv_sec  = ev->time.time.tv_sec;
+                  //p->latency_meas_result.note_on_input_ts.tv_nsec = ev->time.time.tv_nsec;
+                }
+                
                 //printf("%s (%i : %i) (%i)\n", snd_seq_ev_is_abstime(ev)?"abs":"rel",ev->time.time.tv_sec,ev->time.time.tv_nsec, deltaMicroSecs/1000);
                 break;
 
@@ -263,6 +276,18 @@ namespace cw
           }while( snd_seq_event_input_pending(p->h,0));
 
           parser::transmit(p->prvRcvPort->parserH);
+
+          return rc;
+      }
+
+      rc_t _cmMpPoll(device_t* p)
+      {
+        rc_t rc        = kOkRC;
+        int  timeOutMs = 50;
+
+        if (poll(p->alsa_fd, p->alsa_fdCnt, timeOutMs) > 0) 
+        {
+          rc = _handle_alsa_device(p);
         }  
 
         return rc;
@@ -739,6 +764,12 @@ cw::rc_t  cw::midi::device::send( handle_t h, unsigned devIdx, unsigned portIdx,
       ev.type               = SND_SEQ_EVENT_NOTEON;     
       ev.data.note.note     = d0;
       ev.data.note.velocity = d1;
+
+      if( p->latency_meas_enable_out_fl )
+      {
+        p->latency_meas_enable_out_fl = false;
+        time::get(p->latency_meas_result.note_on_output_ts);
+      }
       break;
 
     case kPolyPresMdId: 
@@ -876,6 +907,21 @@ bool        cw::midi::device::usesCallback(    handle_t h, unsigned devIdx, unsi
   return false;
 }
 
+void cw::midi::device::latency_measure_setup(handle_t h)
+{
+  device_t* p  = _handleToPtr(h);
+  
+  p->latency_meas_result.note_on_input_ts  = {0};
+  p->latency_meas_result.note_on_output_ts = {0};
+  p->latency_meas_enable_in_fl           = true;
+  p->latency_meas_enable_out_fl          = true;
+}
+
+cw::midi::device::latency_meas_result_t cw::midi::device::latency_measure_result(handle_t h)
+{
+  device_t* p  = _handleToPtr(h);
+  return p->latency_meas_result;
+}
 
 
 void cw::midi::device::report( handle_t h, textBuf::handle_t tbH )

cwMidiPort.h

@@ -90,6 +90,16 @@ namespace cw
       rc_t removeCallback(  handle_t h, unsigned devIdx, unsigned portIdx, cbFunc_t cbFunc, void* cbDataPtr );
       bool usesCallback(    handle_t h, unsigned devIdx, unsigned portIdx, cbFunc_t cbFunc, void* cbDataPtr );
 
+      typedef struct
+      {
+        time::spec_t note_on_input_ts;
+        time::spec_t note_on_output_ts;
+      } latency_meas_result_t;
+
+      // Reset the latency measurement process.
+      void latency_measure_setup(handle_t h);      
+      latency_meas_result_t latency_measure_result(handle_t h);
+      
       void report( handle_t h, textBuf::handle_t tbH);
       
       rc_t test();