Test for slow snd_rawmidi_drain() with virmidi devices

rawmidi_alsa.c

// gcc rawmidi_alsa.c -o rawmidi_alsa -lasound
// https://www.alsa-project.org/alsa-doc/alsa-lib/group___raw_midi.html
// https://www.alsa-project.org/alsa-doc/alsa-lib/_2test_2rawmidi_8c-example.html
//
// Is there maybe an issue with snd_rawmidi_drain()?
// https://www.mail-archive.com/search?l=alsa-devel@lists.sourceforge.net&q=subject:%22Re%5C%3A+%5C%5BAlsa%5C-devel%5C%5D+Rawmidi+mystery%22&o=newest&f=1

#include <alsa/asoundlib.h>
#include <ctype.h>
#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <unistd.h>

#include "rawmidi_util.h"

int main(int argc,char** argv) {
  char* device = "hw:10,0";
  int drain = 1;
  
  if (argc > 1) {
    device = argv[1];
    if (argc > 2) {
      drain = atoi(argv[2]) != 0;
    }
  }
  printf("Using device '%s' %s draining\n", device, drain ? "with" : "without");

  int err;
  snd_rawmidi_t *handle = 0;
  err = snd_rawmidi_open(NULL,&handle,device,0);
  if (err) {
    fprintf(stderr,"snd_rawmidi_open() %s failed: %d\n",device,err);
    exit(1);
  }
  
  int t = snd_rawmidi_type(handle);
  switch (t) {
    case SND_RAWMIDI_TYPE_HW:
      printf("SND_RAWMIDI_TYPE_HW\n");
      break;
    case SND_RAWMIDI_TYPE_VIRTUAL:
      printf("SND_RAWMIDI_TYPE_VIRTUAL\n");
      break;
    default:
      printf("UNKNOWN\n");
      break;
  }

  // [0] Note on/Channel 0
  // [1] Note number
  // [2] Velocity
  unsigned char note[3] = {0x90, 60, 127};
  int i,j;
  struct timespec ts, te;
  struct stats sw, sd;
  
  init_stats(&sw);
  init_stats(&sd);

  note[2]=127;
  for (j=0; j<2; j++) {
    for (i=0; i<128; i++) {
      note[1]=i;

      clock_gettime(CLOCK_REALTIME, &ts);
      snd_rawmidi_write(handle,note,3);
      clock_gettime(CLOCK_REALTIME, &te);
      update_stats(&sw, timespec_diff(&te,&ts));

      if (drain) {
        clock_gettime(CLOCK_REALTIME, &ts);
        err = snd_rawmidi_drain(handle);
        if (err) {
          fprintf(stderr,"snd_rawmidi_drain() failed: %d\n",err);
        }
        clock_gettime(CLOCK_REALTIME, &te);
        update_stats(&sd, timespec_diff(&te,&ts));
      }
    }
    sleep(1);
    note[2]=0;
  }
  
  print_stats(&sw, "write");
  if (drain) {
    print_stats(&sd, "drain");
  }

  snd_rawmidi_drain(handle); 
  snd_rawmidi_close(handle);  
  return 0;
}

rawmidi_oss.c

// gcc rawmidi_oss.c -o rawmidi_oss
// https://www.alsa-project.org/alsa-doc/alsa-lib/_2test_2rawmidi_8c-example.html

#include <fcntl.h>
#include <linux/soundcard.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

#include "rawmidi_util.h"

int main(int argc,char** argv) {
  char* device =  "/dev/midi10";
  int drain = 1;
  
  if (argc > 1) {
    device = argv[1];
    if (argc > 2) {
      drain = atoi(argv[2]) != 0;
    }
  }
  printf("Using device '%s' %s draining\n", device, drain ? "with" : "without");
  
  int fd = open(device, O_WRONLY, 0);
  if (fd < 0) {
    printf("Error: cannot open %s\n", device);
    exit(1);
  }

  // [0] Note on/Channel 0
  // [1] Note number
  // [2] Velocity
  unsigned char note[3] = {0x90, 60, 127};
  int i,j;
  int rc;
  struct timespec ts, te;
  struct stats sw, sd;
  
  init_stats(&sw);
  init_stats(&sd);

  note[2]=127;
  for (j=0;j<2; j++) {
    for (i=0; i<128; i++) {
      note[1]=i;

      clock_gettime(CLOCK_REALTIME, &ts);
      write(fd, note, sizeof(note));
      clock_gettime(CLOCK_REALTIME, &te);
      update_stats(&sw, timespec_diff(&te,&ts));

      if(drain) {
        clock_gettime(CLOCK_REALTIME, &ts);
        fdatasync(fd);
        clock_gettime(CLOCK_REALTIME, &te);
        update_stats(&sd, timespec_diff(&te,&ts));
      }
    }
    sleep(1);
    note[2]=0;
  }

  print_stats(&sw, "write");
  if (drain) {
    print_stats(&sd, "drain");
  }

  close(fd);
  return 0;
}

rawmidi_util.h

#include <float.h>
#include <time.h>

#define NSEC_TO_MSEC  1000000.0

static double
timespec_diff (struct timespec *te, struct timespec *ts)
{
  if ((te->tv_nsec - ts->tv_nsec) < 0) {
    return (te->tv_sec - ts->tv_sec - 1) + (te->tv_nsec - ts->tv_nsec + 1000000000) / NSEC_TO_MSEC;;
  }
  return (te->tv_sec - ts->tv_sec) + (te->tv_nsec - ts->tv_nsec) / NSEC_TO_MSEC;;
}

struct stats {
  double acc;
  double mi, ma;
  int ct;
};

static void
init_stats(struct stats *s) {
  s->acc=0.0;
  s->mi=DBL_MAX;
  s->ma=DBL_MIN;
  s->ct=0;
}

static void
update_stats(struct stats *s, double td) {
  if(td<s->mi) {
    s->mi=td;
  }
  if(td>s->ma) {
    s->ma=td;
  }
  s->acc += td;
  s->ct++;
}

static void
print_stats(struct stats *s, char *op) {
  double avg=s->acc / s->ct;
  printf("%s took min=%8.4f ms, avg=%8.4f ms, max=%8.4f ms\n", op, s->mi, avg, s->ma);
}