virtio-snd: get recording working on Odroid C4

- we weren't resizing circular queue correctly
- improved error handling in userlevel driver

examples/virtio-snd/userlevel/snd_driver_vm/user_sound/main.c

@@ -11,7 +11,7 @@
 #define PAGE_SIZE_4K 0x1000
 #define RING_BYTES 0x200000
 
-#define SOUND_DEVICE "default"
+#define DEFAULT_DEVICE "default"
 #define MAX_STREAMS 2
 #define UIO_POLLFD 0
 
@@ -249,7 +249,7 @@ static bool handle_uio_interrupt(driver_state_t *state)
     return notify_client;
 }
 
-int main(void)
+int main(int argc, char **argv)
 {
     system("alsactl init -U");
 
@@ -292,14 +292,23 @@ int main(void)
             sddf_snd_pcm_data_ring_t *pcm_responses
                 = direction == SND_PCM_STREAM_PLAYBACK ? state.rings.tx_res : state.rings.rx_res;
 
+            char *device_name;
+            if (argc - 1 > i) {
+                device_name = argv[i+1];
+            } else {
+                device_name = DEFAULT_DEVICE;
+            }
+
             state.streams[state.stream_count] = stream_open(
-                &state.shared_state->stream_info[state.stream_count], SOUND_DEVICE, direction,
+                &state.shared_state->stream_info[state.stream_count], device_name, direction,
                 translate_offset(&state.translate, direction), state.rings.responses, pcm_responses);
 
-            if (state.streams[state.stream_count] == NULL)
-                LOG_SOUND_WARN("Could not initialise target stream %d\n", i);
-            else
+            if (state.streams[state.stream_count] == NULL) {
+                LOG_SOUND_WARN("Could not initialise target stream %d (%s)\n", i, device_name);
+            } else {
+                LOG_SOUND("Initialised stream %d (%s)\n", i, device_name);
                 state.stream_count++;
+            }
         }
 
         if (state.stream_count == 0) {
@@ -360,15 +369,14 @@ int main(void)
                 LOG_SOUND_ERR("Failed to read interrupt\n");
                 break;
             }
-
-            if (handle_uio_interrupt(&state)) {
-                signal_vmm = true;
-            }
-
             if (write(uio_fd, &enable, sizeof(uint32_t)) != sizeof(uint32_t)) {
                 LOG_SOUND_ERR("Failed to reenable interrupts\n");
                 break;
             }
+
+            if (handle_uio_interrupt(&state)) {
+                signal_vmm = true;
+            }
         }
 
         for (int i = 1; i <= state.stream_count; i++) {

examples/virtio-snd/userlevel/snd_driver_vm/user_sound/queue.c

@@ -47,9 +47,7 @@ static void pcm_queue_resize(queue_t *queue)
     queue->data = realloc(queue->data, queue->item_size * queue->capacity);
     assert(queue->data);
 
-    if (queue->head > tail) {
-        memcpy(queue->data + queue->item_size * queue->len, queue->data, tail * queue->item_size);
-    }
+    memcpy(queue->data + queue->item_size * queue->len, queue->data, tail * queue->item_size);
 }
 
 void queue_enqueue(queue_t *queue, const void *item)

examples/virtio-snd/userlevel/snd_driver_vm/user_sound/stream.c

@@ -213,6 +213,7 @@ static int flush_pcm(stream_t *stream, int max_count)
 
     if (avail < 0) {
         LOG_SOUND_ERR("Failed to get avail: %s\n", snd_strerror(avail));
+        stream->state = STREAM_STATE_IO_ERR;
         return response_count;
     }
 
@@ -260,6 +261,7 @@ static int flush_pcm(stream_t *stream, int max_count)
         int err = snd_pcm_start(stream->handle);
         if (err < 0) {
             LOG_SOUND_ERR("Failed to start ALSA stream for playback\n");
+            stream->state = STREAM_STATE_IO_ERR;
             return SDDF_SND_S_IO_ERR;
         }
     }
@@ -486,6 +488,39 @@ static sddf_snd_status_code_t stream_release(stream_t *stream)
     return SDDF_SND_S_OK;
 }
 
+static sddf_snd_status_code_t timer_start(stream_t *stream)
+{
+    // Repeat every period, start immediately.
+    struct itimerspec timer;
+    timer.it_interval.tv_sec = 0;
+    timer.it_interval.tv_nsec = (NS_PER_SECOND / (long)stream->rate) * stream->period_size;
+    timer.it_value.tv_sec = 0;
+    timer.it_value.tv_nsec = 1;
+
+    if (timerfd_settime(stream->timer_fd, 0, &timer, NULL) != 0) {
+        LOG_SOUND_ERR("Failed to set period timer\n");
+        return SDDF_SND_S_IO_ERR;
+    }
+    stream->timer_enabled = true;
+    return SDDF_SND_S_OK;
+}
+
+static sddf_snd_status_code_t timer_stop(stream_t *stream)
+{
+    // Finished drain, disable timer.
+    struct itimerspec timer;
+    timer.it_interval.tv_sec = 0;
+    timer.it_interval.tv_nsec = 0;
+    timer.it_value.tv_sec = 0;
+    timer.it_value.tv_nsec = 0;
+    if (timerfd_settime(stream->timer_fd, 0, &timer, NULL) != 0) {
+        LOG_SOUND_ERR("Failed to set period timer\n");
+        return SDDF_SND_S_IO_ERR;
+    }
+    stream->timer_enabled = false;
+    return SDDF_SND_S_OK;
+}
+
 static sddf_snd_status_code_t stream_start(stream_t *stream)
 {
     if (stream->state != STREAM_STATE_PAUSED) {
@@ -505,17 +540,7 @@ static sddf_snd_status_code_t stream_start(stream_t *stream)
     LOG_SOUND("[%s] Starting stream\n", stream_name(stream));
     stream->state = STREAM_STATE_PLAYING;
 
-    // Repeat every period, start immediately.
-    struct itimerspec timer;
-    timer.it_interval.tv_sec = 0;
-    timer.it_interval.tv_nsec = (NS_PER_SECOND / (long)stream->rate) * stream->period_size;
-    timer.it_value.tv_sec = 0;
-    timer.it_value.tv_nsec = 1;
-
-    if (timerfd_settime(stream->timer_fd, 0, &timer, NULL) != 0) {
-        LOG_SOUND_ERR("Failed to set period timer\n");
-    }
-    stream->timer_enabled = true;
+    sddf_snd_status_code_t status = timer_start(stream);
 
     // Drop any TX frames sent before START.
     if (stream->direction == SND_PCM_STREAM_PLAYBACK) {
@@ -529,7 +554,7 @@ static sddf_snd_status_code_t stream_start(stream_t *stream)
         }
     }
 
-    return SDDF_SND_S_OK;
+    return status;
 }
 
 static sddf_snd_status_code_t stream_stop(stream_t *stream, bool *blocked, bool *notify)
@@ -552,17 +577,19 @@ static sddf_snd_status_code_t stream_stop(stream_t *stream, bool *blocked, bool
                stream->drain_count);
     }
 
-    int nflushed = flush_pcm(stream, stream->drain_count);
-    if (nflushed > 0) {
-        *notify = true;
-    }
+    if (stream->state != STREAM_STATE_IO_ERR) {
+        int nflushed = flush_pcm(stream, stream->drain_count);
+        if (nflushed > 0) {
+            *notify = true;
+        }
 
-    stream->drain_count -= nflushed;
-    assert(stream->drain_count >= 0);
+        stream->drain_count -= nflushed;
+        assert(stream->drain_count >= 0);
 
-    if (stream->drain_count > 0) {
-        *blocked = true;
-        return SDDF_SND_S_OK;
+        if (stream->drain_count > 0) {
+            *blocked = true;
+            return SDDF_SND_S_OK;
+        }
     }
 
     // Flush remaining responses gradually
@@ -581,22 +608,19 @@ static sddf_snd_status_code_t stream_stop(stream_t *stream, bool *blocked, bool
 
     } else if (err < 0) {
         LOG_SOUND_ERR("Failed to drain stream: %s\n", snd_strerror(err));
+        stream->state = STREAM_STATE_IO_ERR;
         return SDDF_SND_S_IO_ERR;
     } else {
         // Flush remaining responses immediately
         while (send_response(stream))
             ;
 
-        // Finished drain, disable timer.
-        struct itimerspec timer;
-        timer.it_interval.tv_sec = 0;
-        timer.it_interval.tv_nsec = 0;
-        timer.it_value.tv_sec = 0;
-        timer.it_value.tv_nsec = 0;
-        if (timerfd_settime(stream->timer_fd, 0, &timer, NULL) != 0) {
-            LOG_SOUND_ERR("Failed to set period timer\n");
+        sddf_snd_status_code_t status = timer_stop(stream);
+
+        if (status == SDDF_SND_S_IO_ERR) {
+            stream->state = STREAM_STATE_IO_ERR;
+            return SDDF_SND_S_IO_ERR;
         }
-        stream->timer_enabled = false;
 
         stream->state = STREAM_STATE_PAUSED;
         LOG_SOUND("[%s] Stream stopped\n", stream_name(stream));

src/virtio/sound.c

@@ -62,9 +62,6 @@ static buffer_queue_t rx_buffers;
 static buffer_t tx_buffer_data[BUFFER_QUEUE_SIZE];
 static buffer_t rx_buffer_data[BUFFER_QUEUE_SIZE];
 
-static int outlying_tx = 0;
-static int outlying_rx = 0;
-
 static sddf_snd_state_t *get_state(struct virtio_device *dev)
 {
     // @alexbr: currently this casts from a void ** which doesn't make sense.
@@ -157,8 +154,6 @@ static void fetch_buffers(struct virtio_device *dev)
 {
     sddf_snd_state_t *state = get_state(dev);
 
-    LOG_SOUND("Fetching buffers\n");
-
     sddf_snd_pcm_data_t pcm;
     while (sddf_snd_dequeue_pcm_data(state->rings.tx_res, &pcm) == 0) {
         buffer_queue_enqueue(&tx_buffers, pcm.addr, pcm.len);
@@ -577,8 +572,6 @@ static void handle_control_msg(struct virtio_device *dev,
     struct virtq_desc *status_desc = &virtq->desc[req_desc->next];
     uint32_t *status_ptr = (void *)status_desc->addr;
 
-    LOG_SOUND("Got command %s\n", code_to_str(hdr->code));
-
     switch (hdr->code) {
     case VIRTIO_SND_R_PCM_INFO: {
 
@@ -700,11 +693,6 @@ static void handle_xfer(struct virtio_device *dev,
 
     msg_handle_t *msg = msg_store_get(&messages, msg_id);
 
-    if (transmit)
-        outlying_tx++;
-    else
-        outlying_rx++;
-
     buffer_t pcm_buffer;
     if (!buffer_queue_dequeue(free_buffers, &pcm_buffer)) {
         LOG_SOUND_ERR("No free buffers\n");
@@ -716,7 +704,7 @@ static void handle_xfer(struct virtio_device *dev,
     uint32_t pcm_remaining = SDDF_SND_PCM_BUFFER_SIZE;
 
     // if (transmit)
-    //     LOG_SOUND("XFER desc_head %u, cookie %d\n", desc_head, msg_id);
+    // LOG_SOUND("XFER desc_head %u, cookie %d\n", desc_head, msg_id);
 
     // int desc_idx = 0;
 
@@ -741,7 +729,7 @@ static void handle_xfer(struct virtio_device *dev,
             int to_xfer = MIN(desc_remaining, pcm_remaining);
 
             // LOG_SOUND("Transmitting chunk of len %u (pcm %u/%u, desc %u/%u)\n", to_transmit,
-            //     pcm_written, pcm_buffer.len, desc_transmitted, desc->len);
+                // pcm_written, pcm_buffer.len, desc_transmitted, desc->len);
 
             if (transmit) {
                 memcpy((void *)pcm_buffer.addr + pcm_transmitted, (void *)desc->addr + desc_transmitted, to_xfer);
@@ -767,6 +755,7 @@ static void handle_xfer(struct virtio_device *dev,
                     goto abort_xfer;
                 }
 
+                // LOG_SOUND("XFER request cookie %d\n", pcm.cookie);
                 msg->ref_count++;
                 *notify_driver = true;
 
@@ -790,6 +779,8 @@ static void handle_xfer(struct virtio_device *dev,
         pcm.status = 0;
         pcm.latency_bytes = 0;
 
+        // LOG_SOUND("XFER request cookie %d\n", pcm.cookie);
+
         if (sddf_snd_enqueue_pcm_data(req_ring, &pcm) != 0) {
             LOG_SOUND_ERR("Failed to enqueue to tx used\n");
             goto abort_xfer;
@@ -936,17 +927,16 @@ static void respond_to_message(struct virtq *virtq, uint8_t status,
         msg->status = status;
     }
 
-    assert(msg->ref_count > 0);
+    if (msg->ref_count == 0) {
+        LOG_SOUND_ERR("Message with cookie %d's ref count is 0 (too many responses)\n", cookie);
+        return;
+    }
     if (--msg->ref_count > 0)
         return;
 
     uint16_t desc_head = msg->desc_head;
     msg_store_remove(&messages, cookie);
 
-    // TODO: remove
-    if (len > sizeof(uint32_t))
-        outlying_tx--;
-
     if (msg->replied) {
         LOG_SOUND_ERR("UIO SND|WARN: message already replied to\n");
         return;
@@ -981,14 +971,18 @@ static void respond_to_message(struct virtq *virtq, uint8_t status,
 
 void handle_rx_response(struct virtio_device *dev, sddf_snd_pcm_data_t *pcm, bool *respond)
 {
+    // LOG_SOUND("Got RX response with len %u, cookie %d\n", pcm->len, pcm->cookie);
+
     msg_handle_t *msg = msg_store_get(&messages, pcm->cookie);
 
     if (pcm->status != SDDF_SND_S_OK) {
         msg->status = pcm->status;
     }
 
-    // TODO: respond
-    assert(msg->ref_count > 0);
+    if (msg->ref_count == 0) {
+        LOG_SOUND_ERR("RX message with cookie %d's ref count is 0 (too many responses)\n", pcm->cookie);
+        return;
+    }
     --msg->ref_count;
 
     virtio_queue_handler_t *vq = &dev->vqs[RXQ];
@@ -1007,9 +1001,6 @@ void handle_rx_response(struct virtio_device *dev, sddf_snd_pcm_data_t *pcm, boo
     void *pcm_data = (void *)pcm->addr;
     unsigned pcm_remaining = pcm->len;
 
-    // LOG_SOUND("RX: pcm len: %u, desc_head %u, bytes_received %u (start)\n", pcm->len, msg->desc_head, msg->bytes_received);
-    // print_bytes(pcm_data);
-
     for (;
         desc->flags & VIRTQ_DESC_F_NEXT;
         desc = &virtq->desc[desc->next])
@@ -1075,7 +1066,7 @@ void handle_rx_response(struct virtio_device *dev, sddf_snd_pcm_data_t *pcm, boo
 
         memcpy((void *)desc->addr, &response, sizeof(response));
 
-        // LOG_SOUND("Responding to RX with %s, desc %u, cookie %u, desc_position %u, outlying %d\n",
+        // LOG_SOUND("Responding to RX with %s, desc %u, cookie %u, desc_position (len) %u, outlying %d\n",
         //         sddf_snd_status_code_str(msg->status), msg->desc_head, pcm->cookie, desc_position,
         //         msg_store_size(&messages));
 
@@ -1084,8 +1075,6 @@ void handle_rx_response(struct virtio_device *dev, sddf_snd_pcm_data_t *pcm, boo
         used_elem->len = desc_position + sizeof(response);
         virtq->used->idx++;
 
-        outlying_rx--;
-
         msg_store_remove(&messages, pcm->cookie);
 
         *respond = true;