Add FASTPATH trace log

Add a trace_fp that can be optimized away when FASTPATH is defined.
This commit is contained in:
Wim Taymans 2019-03-21 11:31:53 +01:00
parent 036ca89c0e
commit 5a2ccee1ff
17 changed files with 98 additions and 87 deletions

View file

@ -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 <xmmintrin.h>
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];

View file

@ -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);
}

View file

@ -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

View file

@ -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

View file

@ -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) {

View file

@ -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;