From 5a2ccee1ff2bafa0e7d2c373def9fe97e921c942 Mon Sep 17 00:00:00 2001 From: Wim Taymans Date: Thu, 21 Mar 2019 11:31:53 +0100 Subject: [PATCH] Add FASTPATH trace log Add a trace_fp that can be optimized away when FASTPATH is defined. --- meson.build | 1 + spa/include/spa/support/log.h | 12 +++++++ spa/plugins/alsa/alsa-sink.c | 4 +-- spa/plugins/alsa/alsa-source.c | 4 +-- spa/plugins/alsa/alsa-utils.c | 32 +++++++++--------- spa/plugins/audioconvert/audioconvert.c | 6 ++-- spa/plugins/audioconvert/channelmix.c | 4 +-- spa/plugins/audioconvert/fmtconvert.c | 6 ++-- spa/plugins/audioconvert/merger.c | 12 +++---- spa/plugins/audioconvert/resample.c | 7 ++-- spa/plugins/audioconvert/splitter.c | 10 +++--- src/modules/module-audio-dsp/floatmix.c | 33 ++++++++++--------- src/modules/module-client-node/client-node.c | 8 ++--- .../module-client-node/client-stream.c | 16 +++------ src/pipewire/log.h | 6 ++++ src/pipewire/node.c | 14 ++++---- src/pipewire/port.c | 10 +++--- 17 files changed, 98 insertions(+), 87 deletions(-) diff --git a/meson.build b/meson.build index 3261cadf9..6807ab174 100644 --- a/meson.build +++ b/meson.build @@ -46,6 +46,7 @@ if cc.get_id() == 'gcc' '-Wsign-compare', '-Wimplicit-fallthrough', '-Wpointer-arith', +# '-DFASTPATH', language : 'c') endif diff --git a/spa/include/spa/support/log.h b/spa/include/spa/support/log.h index 703ed7726..d185102ef 100644 --- a/spa/include/spa/support/log.h +++ b/spa/include/spa/support/log.h @@ -115,6 +115,12 @@ struct spa_log { #define spa_log_debug(l,...) spa_log_log(l,SPA_LOG_LEVEL_DEBUG,__FILE__,__LINE__,__func__,__VA_ARGS__) #define spa_log_trace(l,...) spa_log_log(l,SPA_LOG_LEVEL_TRACE,__FILE__,__LINE__,__func__,__VA_ARGS__) +#ifndef FASTPATH +#define spa_log_trace_fp(l,...) spa_log_log(l,SPA_LOG_LEVEL_TRACE,__FILE__,__LINE__,__func__,__VA_ARGS__) +#else +#define spa_log_trace_fp(l,...) +#endif + #else #define SPA_LOG_FUNC(name,lev) \ @@ -134,6 +140,12 @@ SPA_LOG_FUNC(info, SPA_LOG_LEVEL_INFO) SPA_LOG_FUNC(debug, SPA_LOG_LEVEL_DEBUG) SPA_LOG_FUNC(trace, SPA_LOG_LEVEL_TRACE) +#ifndef FASTPATH +SPA_LOG_FUNC(trace_fp, SPA_LOG_LEVEL_TRACE) +#else +static inline void spa_log_trace_fp (struct spa_log *l, const char *format, ...) { } +#endif + #endif #ifdef __cplusplus } /* extern "C" */ diff --git a/spa/plugins/alsa/alsa-sink.c b/spa/plugins/alsa/alsa-sink.c index 7c3a2ae46..755977c1f 100644 --- a/spa/plugins/alsa/alsa-sink.c +++ b/spa/plugins/alsa/alsa-sink.c @@ -619,7 +619,7 @@ static int impl_node_process(struct spa_node *node) input = this->io; spa_return_val_if_fail(input != NULL, -EIO); - spa_log_trace(this->log, NAME " %p: process %d %d/%d", this, input->status, + spa_log_trace_fp(this->log, NAME " %p: process %d %d/%d", this, input->status, input->buffer_id, this->n_buffers); @@ -633,7 +633,7 @@ static int impl_node_process(struct spa_node *node) input->status = -EINVAL; return -EINVAL; } - spa_log_trace(this->log, NAME " %p: queue buffer %u", this, input->buffer_id); + spa_log_trace_fp(this->log, NAME " %p: queue buffer %u", this, input->buffer_id); spa_list_append(&this->ready, &b->link); SPA_FLAG_UNSET(b->flags, BUFFER_FLAG_OUT); input->buffer_id = SPA_ID_INVALID; diff --git a/spa/plugins/alsa/alsa-source.c b/spa/plugins/alsa/alsa-source.c index 588e56425..bf77aab13 100644 --- a/spa/plugins/alsa/alsa-source.c +++ b/spa/plugins/alsa/alsa-source.c @@ -313,7 +313,7 @@ static void recycle_buffer(struct state *this, uint32_t buffer_id) struct buffer *b = &this->buffers[buffer_id]; if (SPA_FLAG_CHECK(b->flags, BUFFER_FLAG_OUT)) { - spa_log_trace(this->log, NAME " %p: recycle buffer %u", this, buffer_id); + spa_log_trace_fp(this->log, NAME " %p: recycle buffer %u", this, buffer_id); spa_list_append(&this->free, &b->link); SPA_FLAG_UNSET(b->flags, BUFFER_FLAG_OUT); } @@ -653,7 +653,7 @@ static int impl_node_process(struct spa_node *node) b = spa_list_first(&this->ready, struct buffer, link); spa_list_remove(&b->link); - spa_log_trace(this->log, NAME " %p: dequeue buffer %d", node, b->id); + spa_log_trace_fp(this->log, NAME " %p: dequeue buffer %d", node, b->id); io->buffer_id = b->id; io->status = SPA_STATUS_HAVE_BUFFER; diff --git a/spa/plugins/alsa/alsa-utils.c b/spa/plugins/alsa/alsa-utils.c index 0b7a91e4f..504152558 100644 --- a/spa/plugins/alsa/alsa-utils.c +++ b/spa/plugins/alsa/alsa-utils.c @@ -634,7 +634,7 @@ static int update_time(struct state *state, uint64_t nsec, snd_pcm_sframes_t del } #endif - spa_log_trace(state->log, "%"PRIu64" %f %"PRIi64" %"PRIi64" %"PRIi64" %d %"PRIu64" %f %f", nsec, + spa_log_trace_fp(state->log, "%"PRIu64" %f %"PRIi64" %"PRIi64" %"PRIi64" %d %"PRIu64" %f %f", nsec, state->old_dt, delay, elapsed, (int64_t)(nsec - state->last_time), state->threshold, state->next_time, tw, extra); @@ -666,7 +666,7 @@ int spa_alsa_write(struct state *state, snd_pcm_uframes_t silence, bool start) if ((res = update_time(state, nsec, delay, true)) < 0) return res; - spa_log_trace(state->log, "slave %f %"PRIi64" %"PRIu64" %d", + spa_log_trace_fp(state->log, "slave %f %"PRIi64" %"PRIu64" %d", state->dll.dt, nsec, delay, state->rate); if (delay > state->threshold * 2) { @@ -682,7 +682,7 @@ again: spa_log_error(state->log, "snd_pcm_mmap_begin error: %s", snd_strerror(res)); return res; } - spa_log_trace(state->log, "begin %ld %ld %d", offset, frames, state->threshold); + spa_log_trace_fp(state->log, "begin %ld %ld %d", offset, frames, state->threshold); silence = SPA_MIN(silence, frames); to_write = frames; @@ -726,7 +726,7 @@ again: spa_list_remove(&b->link); SPA_FLAG_SET(b->flags, BUFFER_FLAG_OUT); state->io->buffer_id = b->id; - spa_log_trace(state->log, "alsa-util %p: reuse buffer %u", state, b->id); + spa_log_trace_fp(state->log, "alsa-util %p: reuse buffer %u", state, b->id); state->callbacks->reuse_buffer(state->callbacks_data, 0, b->id); state->ready_offset = 0; } @@ -740,12 +740,12 @@ again: } if (silence > 0) { - spa_log_trace(state->log, "silence %ld", silence); + spa_log_trace_fp(state->log, "silence %ld", silence); snd_pcm_areas_silence(my_areas, off, state->channels, silence, state->format); written += silence; } - spa_log_trace(state->log, "commit %ld %ld %"PRIi64, offset, written, state->sample_count); + spa_log_trace_fp(state->log, "commit %ld %ld %"PRIi64, offset, written, state->sample_count); total_written += written; if ((res = snd_pcm_mmap_commit(hndl, offset, written)) < 0) { @@ -840,7 +840,6 @@ static int handle_play(struct state *state) int res; snd_pcm_sframes_t delay; uint64_t nsec; - int64_t jitter; if (state->position && state->threshold != state->position->size) state->threshold = state->position->size; @@ -850,9 +849,9 @@ static int handle_play(struct state *state) return 0; nsec = SPA_TIMESPEC_TO_NSEC(&state->now); - jitter = nsec - state->next_time; - spa_log_trace(state->log, "timeout %ld %"PRIu64" %"PRIu64" %"PRIi64" %d %ld", delay, - nsec, state->next_time, jitter, state->threshold, state->sample_count); + spa_log_trace_fp(state->log, "timeout %ld %"PRIu64" %"PRIu64" %"PRIi64" %d %ld", delay, + nsec, state->next_time, nsec - state->next_time, + state->threshold, state->sample_count); if (delay >= state->threshold * 2) { spa_log_trace(state->log, "early wakeup %ld %d", delay, state->threshold); @@ -866,7 +865,7 @@ static int handle_play(struct state *state) if (spa_list_is_empty(&state->ready)) { struct spa_io_buffers *io = state->io; - spa_log_trace(state->log, "alsa-util %p: %d", state, io->status); + spa_log_trace_fp(state->log, "alsa-util %p: %d", state, io->status); io->status = SPA_STATUS_NEED_BUFFER; if (state->range) { @@ -904,7 +903,6 @@ static void alsa_on_capture_timeout_event(struct spa_source *source) snd_pcm_sframes_t delay; snd_pcm_uframes_t total_read = 0, to_read; const snd_pcm_channel_area_t *my_areas; - int64_t jitter; if (state->started && read(state->timerfd, &expire, sizeof(uint64_t)) != sizeof(uint64_t)) spa_log_warn(state->log, "error reading timerfd: %s", strerror(errno)); @@ -917,9 +915,9 @@ static void alsa_on_capture_timeout_event(struct spa_source *source) return; nsec = SPA_TIMESPEC_TO_NSEC(&state->now); - jitter = nsec - state->next_time; - spa_log_trace(state->log, "timeout %ld %"PRIu64" %"PRIu64" %"PRIi64" %d %ld", delay, - nsec, state->next_time, jitter, state->threshold, state->sample_count); + spa_log_trace_fp(state->log, "timeout %ld %"PRIu64" %"PRIu64" %"PRIi64" %d %ld", delay, + nsec, state->next_time, nsec - state->next_time, + state->threshold, state->sample_count); if (delay < state->threshold) { spa_log_trace(state->log, "early wakeup %ld %d", delay, state->threshold); @@ -936,7 +934,7 @@ static void alsa_on_capture_timeout_event(struct spa_source *source) snd_pcm_uframes_t read, frames, offset; frames = to_read - total_read; - spa_log_trace(state->log, "begin %ld %ld %ld %ld", offset, frames, to_read, total_read); + spa_log_trace_fp(state->log, "begin %ld %ld %ld %ld", offset, frames, to_read, total_read); if ((res = snd_pcm_mmap_begin(hndl, &my_areas, &offset, &frames)) < 0) { spa_log_error(state->log, "snd_pcm_mmap_begin error: %s", snd_strerror(res)); return; @@ -946,7 +944,7 @@ static void alsa_on_capture_timeout_event(struct spa_source *source) if (read < frames) to_read = 0; - spa_log_trace(state->log, "commit %ld %ld", offset, read); + spa_log_trace_fp(state->log, "commit %ld %ld", offset, read); if ((res = snd_pcm_mmap_commit(hndl, offset, read)) < 0) { spa_log_error(state->log, "snd_pcm_mmap_commit error: %s", snd_strerror(res)); if (res != -EPIPE && res != -ESTRPIPE) diff --git a/spa/plugins/audioconvert/audioconvert.c b/spa/plugins/audioconvert/audioconvert.c index 02233d2c3..7c761ec16 100644 --- a/spa/plugins/audioconvert/audioconvert.c +++ b/spa/plugins/audioconvert/audioconvert.c @@ -870,14 +870,14 @@ static int impl_node_process(struct spa_node *node) this = SPA_CONTAINER_OF(node, struct impl, node); - spa_log_trace(this->log, NAME " %p: process %d", this, this->n_links); + spa_log_trace_fp(this->log, NAME " %p: process %d", this, this->n_links); while (1) { res = SPA_STATUS_OK; ready = 0; for (i = 0; i < this->n_nodes; i++) { r = spa_node_process(this->nodes[i]); - spa_log_trace(this->log, NAME " %p: process %d %d", this, i, r); + spa_log_trace_fp(this->log, NAME " %p: process %d %d", this, i, r); if (r < 0) return r; @@ -896,7 +896,7 @@ static int impl_node_process(struct spa_node *node) break; } - spa_log_trace(this->log, NAME " %p: process result: %d", this, res); + spa_log_trace_fp(this->log, NAME " %p: process result: %d", this, res); return res; } diff --git a/spa/plugins/audioconvert/channelmix.c b/spa/plugins/audioconvert/channelmix.c index ff87813d7..6a96e623f 100644 --- a/spa/plugins/audioconvert/channelmix.c +++ b/spa/plugins/audioconvert/channelmix.c @@ -1028,7 +1028,7 @@ static void recycle_buffer(struct impl *this, uint32_t id) if (SPA_FLAG_CHECK(b->flags, BUFFER_FLAG_OUT)) { spa_list_append(&port->queue, &b->link); SPA_FLAG_UNSET(b->flags, BUFFER_FLAG_OUT); - spa_log_trace(this->log, NAME " %p: recycle buffer %d", this, id); + spa_log_trace_fp(this->log, NAME " %p: recycle buffer %d", this, id); } } @@ -1098,7 +1098,7 @@ static int impl_node_process(struct spa_node *node) spa_return_val_if_fail(outio != NULL, -EIO); spa_return_val_if_fail(inio != NULL, -EIO); - spa_log_trace(this->log, NAME " %p: status %d %d", this, inio->status, outio->status); + spa_log_trace_fp(this->log, NAME " %p: status %d %d", this, inio->status, outio->status); if (outport->control) process_control(this, outport, &outport->control->sequence); diff --git a/spa/plugins/audioconvert/fmtconvert.c b/spa/plugins/audioconvert/fmtconvert.c index db6e08252..44c67fd3d 100644 --- a/spa/plugins/audioconvert/fmtconvert.c +++ b/spa/plugins/audioconvert/fmtconvert.c @@ -758,7 +758,7 @@ static void recycle_buffer(struct impl *this, struct port *port, uint32_t id) if (SPA_FLAG_CHECK(b->flags, BUFFER_FLAG_OUT)) { spa_list_append(&port->queue, &b->link); SPA_FLAG_UNSET(b->flags, BUFFER_FLAG_OUT); - spa_log_trace(this->log, NAME " %p: recycle buffer %d", this, id); + spa_log_trace_fp(this->log, NAME " %p: recycle buffer %d", this, id); } } @@ -817,7 +817,7 @@ static int impl_node_process(struct spa_node *node) inio = inport->io; spa_return_val_if_fail(inio != NULL, -EIO); - spa_log_trace(this->log, NAME " %p: status %p %d %d -> %p %d %d", this, + spa_log_trace_fp(this->log, NAME " %p: status %p %d %d -> %p %d %d", this, inio, inio->status, inio->buffer_id, outio, outio->status, outio->buffer_id); @@ -860,7 +860,7 @@ static int impl_node_process(struct spa_node *node) maxsize = SPA_MIN(outport->ctrl->max_size, maxsize); n_samples = SPA_MIN(n_samples, maxsize / outport->stride); - spa_log_trace(this->log, NAME " %p: n_src:%d n_dst:%d size:%d maxsize:%d n_samples:%d", + spa_log_trace_fp(this->log, NAME " %p: n_src:%d n_dst:%d size:%d maxsize:%d n_samples:%d", this, n_src_datas, n_dst_datas, size, maxsize, n_samples); n_datas = SPA_MAX(n_src_datas, n_dst_datas); diff --git a/spa/plugins/audioconvert/merger.c b/spa/plugins/audioconvert/merger.c index db6aad728..dd6c5531b 100644 --- a/spa/plugins/audioconvert/merger.c +++ b/spa/plugins/audioconvert/merger.c @@ -714,7 +714,7 @@ static void queue_buffer(struct impl *this, struct port *port, uint32_t id) { struct buffer *b = &port->buffers[id]; - spa_log_trace(this->log, NAME " %p: queue buffer %d on port %d %d", + spa_log_trace_fp(this->log, NAME " %p: queue buffer %d on port %d %d", this, id, port->id, b->flags); if (SPA_FLAG_CHECK(b->flags, BUFFER_FLAG_QUEUED)) return; @@ -733,7 +733,7 @@ static struct buffer *dequeue_buffer(struct impl *this, struct port *port) b = spa_list_first(&port->queue, struct buffer, link); spa_list_remove(&b->link); SPA_FLAG_UNSET(b->flags, BUFFER_FLAG_QUEUED); - spa_log_trace(this->log, NAME " %p: dequeue buffer %d on port %d %u", + spa_log_trace_fp(this->log, NAME " %p: dequeue buffer %d on port %d %u", this, b->id, port->id, b->flags); return b; @@ -872,7 +872,7 @@ static inline int get_in_buffer(struct impl *this, struct port *port, struct buf if ((io = port->io) == NULL || io->status != SPA_STATUS_HAVE_BUFFER || io->buffer_id >= port->n_buffers) { - spa_log_trace(this->log, NAME " %p: empty port %d %p %d %d %d", + spa_log_trace_fp(this->log, NAME " %p: empty port %d %p %d %d %d", this, port->id, io, io->status, io->buffer_id, port->n_buffers); return -EPIPE; @@ -944,7 +944,7 @@ static int impl_node_process(struct spa_node *node) spa_return_val_if_fail(outio != NULL, -EIO); spa_return_val_if_fail(this->convert != NULL, -EIO); - spa_log_trace(this->log, NAME " %p: status %d %d", this, outio->status, outio->buffer_id); + spa_log_trace_fp(this->log, NAME " %p: status %d %d", this, outio->status, outio->buffer_id); if ((res = get_out_buffer(this, outport, &dbuf)) != 0) return res; @@ -977,7 +977,7 @@ static int impl_node_process(struct spa_node *node) n_samples = SPA_MIN(n_samples, sd->chunk->size / inport->stride); - spa_log_trace(this->log, NAME " %p: %d %d %d %p", this, + spa_log_trace_fp(this->log, NAME " %p: %d %d %d %p", this, sd->chunk->size, maxsize, n_samples, src_datas[i]); SPA_FLAG_SET(res, SPA_STATUS_NEED_BUFFER); @@ -991,7 +991,7 @@ static int impl_node_process(struct spa_node *node) dbuf->buf->datas[i].data = dst_datas[i]; dbuf->buf->datas[i].chunk->offset = 0; dbuf->buf->datas[i].chunk->size = n_samples * outport->stride; - spa_log_trace(this->log, NAME " %p %p %d", this, dst_datas[i], + spa_log_trace_fp(this->log, NAME " %p %p %d", this, dst_datas[i], n_samples * outport->stride); } if (!this->is_passthrough) diff --git a/spa/plugins/audioconvert/resample.c b/spa/plugins/audioconvert/resample.c index 72f1f3683..c2876ba66 100644 --- a/spa/plugins/audioconvert/resample.c +++ b/spa/plugins/audioconvert/resample.c @@ -669,7 +669,7 @@ static void recycle_buffer(struct impl *this, uint32_t id) if (SPA_FLAG_CHECK(b->flags, BUFFER_FLAG_OUT)) { spa_list_append(&port->queue, &b->link); SPA_FLAG_UNSET(b->flags, BUFFER_FLAG_OUT); - spa_log_trace(this->log, NAME " %p: recycle buffer %d", this, id); + spa_log_trace_fp(this->log, NAME " %p: recycle buffer %d", this, id); } } @@ -744,7 +744,8 @@ static int impl_node_process(struct spa_node *node) spa_return_val_if_fail(outio != NULL, -EIO); spa_return_val_if_fail(inio != NULL, -EIO); - spa_log_trace(this->log, NAME " %p: status %d %d %p", this, inio->status, outio->status, outport->io_control); + spa_log_trace_fp(this->log, NAME " %p: status %d %d %p", + this, inio->status, outio->status, outport->io_control); if (outport->io_control) process_control(this, outport, &outport->io_control->sequence); @@ -791,7 +792,7 @@ static int impl_node_process(struct spa_node *node) resample_process(&this->resample, i, src, &in_len, dst, &out_len); - spa_log_trace(this->log, NAME " %p: in %d/%d %ld %d out %d/%d %ld %d", + spa_log_trace_fp(this->log, NAME " %p: in %d/%d %ld %d out %d/%d %ld %d", this, pin_len, in_len, size / sizeof(float), inport->offset, pout_len, out_len, maxsize / sizeof(float), outport->offset); diff --git a/spa/plugins/audioconvert/splitter.c b/spa/plugins/audioconvert/splitter.c index 079467b5a..78b198fb7 100644 --- a/spa/plugins/audioconvert/splitter.c +++ b/spa/plugins/audioconvert/splitter.c @@ -683,7 +683,7 @@ static void queue_buffer(struct impl *this, struct port *port, uint32_t id) { struct buffer *b = &port->buffers[id]; - spa_log_trace(this->log, NAME " %p: queue buffer %d on port %d %d", + spa_log_trace_fp(this->log, NAME " %p: queue buffer %d on port %d %d", this, id, port->id, b->flags); if (SPA_FLAG_CHECK(b->flags, BUFFER_FLAG_QUEUED)) return; @@ -702,7 +702,7 @@ static struct buffer *dequeue_buffer(struct impl *this, struct port *port) b = spa_list_first(&port->queue, struct buffer, link); spa_list_remove(&b->link); SPA_FLAG_UNSET(b->flags, BUFFER_FLAG_QUEUED); - spa_log_trace(this->log, NAME " %p: dequeue buffer %d on port %d %u", + spa_log_trace_fp(this->log, NAME " %p: dequeue buffer %d on port %d %u", this, b->id, port->id, b->flags); return b; @@ -848,7 +848,7 @@ static int impl_node_process(struct spa_node *node) spa_return_val_if_fail(inio != NULL, -EIO); spa_return_val_if_fail(this->convert != NULL, -EIO); - spa_log_trace(this->log, NAME " %p: status %p %d %d", this, + spa_log_trace_fp(this->log, NAME " %p: status %p %d %d", this, inio, inio->status, inio->buffer_id); if (inio->status != SPA_STATUS_HAVE_BUFFER) @@ -880,7 +880,7 @@ static int impl_node_process(struct spa_node *node) if ((outio = outport->io) == NULL) goto empty; - spa_log_trace(this->log, NAME " %p: %d %p %d %d %d", this, i, + spa_log_trace_fp(this->log, NAME " %p: %d %p %d %d %d", this, i, outio, outio->status, outio->buffer_id, outport->stride); if (outio->status == SPA_STATUS_HAVE_BUFFER) { @@ -920,7 +920,7 @@ static int impl_node_process(struct spa_node *node) res |= SPA_STATUS_HAVE_BUFFER; } - spa_log_trace(this->log, NAME " %p: %d %d %d %d %d", this, + spa_log_trace_fp(this->log, NAME " %p: %d %d %d %d %d", this, n_src_datas, n_dst_datas, n_samples, maxsize, inport->stride); if (!this->is_passthrough) diff --git a/src/modules/module-audio-dsp/floatmix.c b/src/modules/module-audio-dsp/floatmix.c index 32921fde0..f7d2aff1d 100644 --- a/src/modules/module-audio-dsp/floatmix.c +++ b/src/modules/module-audio-dsp/floatmix.c @@ -465,7 +465,7 @@ static int queue_buffer(struct impl *this, struct port *port, struct buffer *b) spa_list_append(&port->queue, &b->link); SPA_FLAG_SET(b->flags, BUFFER_FLAG_QUEUED); - spa_log_trace(this->log, NAME " %p: queue buffer %d", this, b->id); + spa_log_trace_fp(this->log, NAME " %p: queue buffer %d", this, b->id); return 0; } @@ -479,7 +479,7 @@ static struct buffer *dequeue_buffer(struct impl *this, struct port *port) b = spa_list_first(&port->queue, struct buffer, link); spa_list_remove(&b->link); SPA_FLAG_UNSET(b->flags, BUFFER_FLAG_QUEUED); - spa_log_trace(this->log, NAME " %p: dequeue buffer %d", this, b->id); + spa_log_trace_fp(this->log, NAME " %p: dequeue buffer %d", this, b->id); return b; } @@ -684,10 +684,11 @@ static int impl_node_port_reuse_buffer(struct spa_node *node, uint32_t port_id, #if defined (__SSE__) #include -static void mix_2(float *dst, float *src1, float *src2, int n_samples) +static void mix_2(float * dst, const float * SPA_RESTRICT src1, + const float * SPA_RESTRICT src2, uint32_t n_samples) { - int n, unrolled; - __m128 in[2]; + uint32_t n, unrolled; + __m128 in1[4], in2[4]; if (SPA_IS_ALIGNED(src1, 16) && SPA_IS_ALIGNED(src2, 16) && @@ -697,8 +698,6 @@ static void mix_2(float *dst, float *src1, float *src2, int n_samples) unrolled = 0; for (n = 0; unrolled--; n += 16) { - __m128 in1[4], in2[4]; - in1[0] = _mm_load_ps(&src1[n+ 0]); in1[1] = _mm_load_ps(&src1[n+ 4]); in1[2] = _mm_load_ps(&src1[n+ 8]); @@ -720,16 +719,17 @@ static void mix_2(float *dst, float *src1, float *src2, int n_samples) _mm_store_ps(&dst[n+12], in1[3]); } for (; n < n_samples; n++) { - in[0] = _mm_load_ss(&src1[n]), - in[1] = _mm_load_ss(&src2[n]), - in[0] = _mm_add_ss(in[0], in[1]); - _mm_store_ss(&dst[n], in[0]); + in1[0] = _mm_load_ss(&src1[n]), + in2[0] = _mm_load_ss(&src2[n]), + in1[0] = _mm_add_ss(in1[0], in2[0]); + _mm_store_ss(&dst[n], in1[0]); } } #else -static void mix_2(float *dst, float *src1, float *src2, int n_samples) +static void mix_2(float * dst, const float * SPA_RESTRICT src1, + const float * SPA_RESTRICT src2, uint32_t n_samples) { - int i; + uint32_t i; for (i = 0; i < n_samples; i++) dst[i] = src1[i] + src2[i]; } @@ -753,7 +753,8 @@ static int impl_node_process(struct spa_node *node) outio = outport->io; spa_return_val_if_fail(outio != NULL, -EIO); - spa_log_trace(this->log, NAME " %p: status %p %d %d", this, outio, outio->status, outio->buffer_id); + spa_log_trace_fp(this->log, NAME " %p: status %p %d %d", + this, outio, outio->status, outio->buffer_id); if (outio->status == SPA_STATUS_HAVE_BUFFER) return outio->status; @@ -780,7 +781,7 @@ static int impl_node_process(struct spa_node *node) (inio = inport->io) == NULL || inio->buffer_id >= inport->n_buffers || inio->status != SPA_STATUS_HAVE_BUFFER) { - spa_log_trace(this->log, NAME " %p: skip input %d %d %p %d %d %d", this, + spa_log_trace_fp(this->log, NAME " %p: skip input %d %d %p %d %d %d", this, i, inport->valid, inio, inio ? inio->status : -1, inio ? inio->buffer_id : SPA_ID_INVALID, @@ -788,7 +789,7 @@ static int impl_node_process(struct spa_node *node) continue; } - spa_log_trace(this->log, NAME " %p: mix input %d %p->%p %d %d", this, + spa_log_trace_fp(this->log, NAME " %p: mix input %d %p->%p %d %d", this, i, inio, outio, inio->status, inio->buffer_id); inb = &inport->buffers[inio->buffer_id]; diff --git a/src/modules/module-client-node/client-node.c b/src/modules/module-client-node/client-node.c index beb03b3fc..8f9234741 100644 --- a/src/modules/module-client-node/client-node.c +++ b/src/modules/module-client-node/client-node.c @@ -964,7 +964,7 @@ impl_node_port_reuse_buffer(struct spa_node *node, uint32_t port_id, uint32_t bu spa_return_val_if_fail(CHECK_OUT_PORT(this, SPA_DIRECTION_OUTPUT, port_id), -EINVAL); - spa_log_trace(this->log, "reuse buffer %d", buffer_id); + spa_log_trace_fp(this->log, "reuse buffer %d", buffer_id); return -ENOTSUP; } @@ -977,7 +977,7 @@ static int impl_node_process(struct spa_node *node) struct timespec ts; uint64_t cmd = 1; - spa_log_trace(this->log, "%p: send process %p", this, impl->this.node->driver_node); + spa_log_trace_fp(this->log, "%p: send process %p", this, impl->this.node->driver_node); clock_gettime(CLOCK_MONOTONIC, &ts); n->rt.activation->status = TRIGGERED; @@ -1114,7 +1114,7 @@ static void node_on_data_fd_events(struct spa_source *source) if (read(this->data_source.fd, &cmd, sizeof(cmd)) != sizeof(cmd) || cmd != 1) spa_log_warn(this->log, "node %p: read %"PRIu64" failed %m", this, cmd); - spa_log_trace(this->log, "node %p: got ready", this); + spa_log_trace_fp(this->log, "node %p: got ready", this); if (this->callbacks && this->callbacks->ready) this->callbacks->ready(this->callbacks_data, SPA_STATUS_HAVE_BUFFER); } @@ -1616,7 +1616,7 @@ static const struct pw_resource_events resource_events = { static int process_node(void *data) { struct impl *impl = data; - pw_log_trace("client-node %p: process", impl); + pw_log_trace_fp("client-node %p: process", impl); return spa_node_process(&impl->node.node); } diff --git a/src/modules/module-client-node/client-stream.c b/src/modules/module-client-node/client-stream.c index 00db66719..8baeeb165 100644 --- a/src/modules/module-client-node/client-stream.c +++ b/src/modules/module-client-node/client-stream.c @@ -854,7 +854,7 @@ static int impl_node_process(struct spa_node *node) impl->range.min_size = impl->range.max_size = q->size * sizeof(float); - spa_log_trace(this->log, "%p: process %d", this, impl->range.max_size); + spa_log_trace_fp(this->log, "%p: process %d", this, impl->range.max_size); if (impl->use_converter) { status = spa_node_process(impl->adapter); @@ -862,7 +862,7 @@ static int impl_node_process(struct spa_node *node) else { struct spa_io_buffers tmp; - spa_log_trace(this->log, "%p: process %d/%d %d/%d", this, + spa_log_trace_fp(this->log, "%p: process %d/%d %d/%d", this, impl->io->status, impl->io->buffer_id, impl->client_port_mix.io->status, impl->client_port_mix.io->buffer_id); @@ -873,7 +873,7 @@ static int impl_node_process(struct spa_node *node) status = impl->client_port_mix.io->status | impl->io->status; } - spa_log_trace(this->log, "%p: process %d", this, status); + spa_log_trace_fp(this->log, "%p: process %d", this, status); if (impl->direction == SPA_DIRECTION_OUTPUT) { if (!(status & SPA_STATUS_HAVE_BUFFER)) @@ -1225,7 +1225,7 @@ static const struct pw_node_events node_events = { static int node_ready(void *data, int status) { struct impl *impl = data; - pw_log_trace("client-stream %p: ready %d", &impl->this, status); + pw_log_trace_fp("client-stream %p: ready %d", &impl->this, status); impl->driver = false; impl_node_process(&impl->node.node); @@ -1234,17 +1234,9 @@ static int node_ready(void *data, int status) return impl->node.callbacks->ready(impl->node.callbacks_data, status); } -static int node_reuse_buffer(void *data, uint32_t port_id, uint32_t buffer_id) -{ - struct impl *impl = data; - pw_log_trace("client-stream %p: reuse_buffer %d", &impl->this, buffer_id); - return 0; -} - static const struct spa_node_callbacks node_callbacks = { SPA_VERSION_NODE_CALLBACKS, .ready = node_ready, - .reuse_buffer = node_reuse_buffer, }; /** Create a new client stream diff --git a/src/pipewire/log.h b/src/pipewire/log.h index b7f92eb4e..7b9eea708 100644 --- a/src/pipewire/log.h +++ b/src/pipewire/log.h @@ -78,6 +78,12 @@ pw_log_logv(enum spa_log_level level, #define pw_log_debug(...) pw_log(SPA_LOG_LEVEL_DEBUG,__VA_ARGS__) #define pw_log_trace(...) pw_log(SPA_LOG_LEVEL_TRACE,__VA_ARGS__) +#ifndef FASTPATH +#define pw_log_trace_fp(...) pw_log(SPA_LOG_LEVEL_TRACE,__VA_ARGS__) +#else +#define pw_log_trace_fp(...) +#endif + #ifdef __cplusplus } #endif diff --git a/src/pipewire/node.c b/src/pipewire/node.c index 8ea23f5e1..92752fb93 100644 --- a/src/pipewire/node.c +++ b/src/pipewire/node.c @@ -711,14 +711,14 @@ static inline int resume_node(struct pw_node *this, int status) activation->status = FINISHED; activation->finish_time = nsec; - pw_log_trace("node %p: trigger peers", this); + pw_log_trace_fp("node %p: trigger peers", this); spa_list_for_each(t, &this->rt.target_list, link) { struct pw_node_activation_state *state; state = &t->activation->state[0]; - spa_debug("node %p: state %p pending %d/%d", t->node, state, + pw_log_trace_fp("node %p: state %p pending %d/%d", t->node, state, state->pending, state->required); if (pw_node_activation_state_dec(state, 1)) { @@ -738,7 +738,7 @@ static inline int process_node(void *data) struct pw_node_activation *a = this->rt.activation; int status; - pw_log_trace("node %p: process", this); + pw_log_trace_fp("node %p: process", this); clock_gettime(CLOCK_MONOTONIC, &ts); a->status = AWAKE; @@ -756,11 +756,11 @@ static inline int process_node(void *data) a->signal_time = a->finish_time; a->finish_time = SPA_TIMESPEC_TO_NSEC(&ts); a->running = false; - pw_log_trace("node %p: graph completed wait:%"PRIu64" run:%"PRIu64, this, + pw_log_trace_fp("node %p: graph completed wait:%"PRIu64" run:%"PRIu64, this, a->awake_time - a->signal_time, a->finish_time - a->awake_time); } else if (status == SPA_STATUS_OK) { - pw_log_trace("node %p: async continue", this); + pw_log_trace_fp("node %p: async continue", this); } else { resume_node(this, status); } @@ -782,7 +782,7 @@ static void node_on_fd_events(struct spa_source *source) if (read(this->source.fd, &cmd, sizeof(cmd)) != sizeof(cmd) || cmd != 1) pw_log_warn("node %p: read %"PRIu64" failed %m", this, cmd); - pw_log_trace("node %p: got process", this); + pw_log_trace_fp("node %p: got process", this); this->rt.target.signal(this->rt.target.data); } } @@ -1065,7 +1065,7 @@ static int node_ready(void *data, int status) struct pw_node *driver = node->driver_node; struct pw_node_target *t; - pw_log_trace("node %p: ready driver:%d exported:%d %p status:%d", node, + pw_log_trace_fp("node %p: ready driver:%d exported:%d %p status:%d", node, node->driver, node->exported, driver, status); if (node == driver) { diff --git a/src/pipewire/port.c b/src/pipewire/port.c index 7dbed0974..1f94a294c 100644 --- a/src/pipewire/port.c +++ b/src/pipewire/port.c @@ -88,9 +88,9 @@ static int tee_process(struct spa_node *data) struct pw_port_mix *mix; struct spa_io_buffers *io = &this->rt.io; - pw_log_trace("port %p: tee input %d %d", this, io->status, io->buffer_id); + pw_log_trace_fp("port %p: tee input %d %d", this, io->status, io->buffer_id); spa_list_for_each(mix, &this->rt.mix_list, rt_link) { - pw_log_trace("port %p: port %d %p->%p %d", this, + pw_log_trace_fp("port %p: port %d %p->%p %d", this, mix->port.port_id, io, mix->io, mix->io->buffer_id); *mix->io = *io; } @@ -104,7 +104,7 @@ static int tee_reuse_buffer(struct spa_node *data, uint32_t port_id, uint32_t bu struct impl *impl = SPA_CONTAINER_OF(data, struct impl, mix_node); struct pw_port *this = &impl->this; - pw_log_trace("port %p: tee reuse buffer %d %d", this, port_id, buffer_id); + pw_log_trace_fp("port %p: tee reuse buffer %d %d", this, port_id, buffer_id); spa_node_port_reuse_buffer(this->node->node, this->port_id, buffer_id); return 0; @@ -128,7 +128,7 @@ static int schedule_mix_input(struct spa_node *data) return SPA_STATUS_HAVE_BUFFER | SPA_STATUS_NEED_BUFFER; spa_list_for_each(mix, &this->rt.mix_list, rt_link) { - pw_log_trace("port %p: mix input %d %p->%p %d %d", this, + pw_log_trace_fp("port %p: mix input %d %p->%p %d %d", this, mix->port.port_id, mix->io, io, mix->io->status, mix->io->buffer_id); *io = *mix->io; mix->io->status = SPA_STATUS_NEED_BUFFER; @@ -144,7 +144,7 @@ static int schedule_mix_reuse_buffer(struct spa_node *data, uint32_t port_id, ui struct pw_port_mix *mix; spa_list_for_each(mix, &this->rt.mix_list, rt_link) { - pw_log_trace("port %p: reuse buffer %d %d", this, port_id, buffer_id); + pw_log_trace_fp("port %p: reuse buffer %d %d", this, port_id, buffer_id); spa_node_port_reuse_buffer(this->node->node, port_id, buffer_id); } return 0;