ipc3-dtrace.c

  1// SPDX-License-Identifier: GPL-2.0-only
  2//
  3// Copyright(c) 2022 Intel Corporation
  4//
  5// Author: Liam Girdwood <liam.r.girdwood@linux.intel.com>
  6
  7#include <linux/debugfs.h>
  8#include <linux/sched/signal.h>
  9#include "sof-priv.h"
 10#include "sof-audio.h"
 11#include "ops.h"
 12#include "sof-utils.h"
 13#include "ipc3-priv.h"
 14
 15#define TRACE_FILTER_ELEMENTS_PER_ENTRY 4
 16#define TRACE_FILTER_MAX_CONFIG_STRING_LENGTH 1024
 17
 18enum sof_dtrace_state {
 19	SOF_DTRACE_DISABLED,
 20	SOF_DTRACE_STOPPED,
 21	SOF_DTRACE_INITIALIZING,
 22	SOF_DTRACE_ENABLED,
 23};
 24
 25struct sof_dtrace_priv {
 26	struct snd_dma_buffer dmatb;
 27	struct snd_dma_buffer dmatp;
 28	int dma_trace_pages;
 29	wait_queue_head_t trace_sleep;
 30	u32 host_offset;
 31	bool dtrace_error;
 32	bool dtrace_draining;
 33	enum sof_dtrace_state dtrace_state;
 34};
 35
 36static bool trace_pos_update_expected(struct sof_dtrace_priv *priv)
 37{
 38	if (priv->dtrace_state == SOF_DTRACE_ENABLED ||
 39	    priv->dtrace_state == SOF_DTRACE_INITIALIZING)
 40		return true;
 41
 42	return false;
 43}
 44
 45static int trace_filter_append_elem(struct snd_sof_dev *sdev, u32 key, u32 value,
 46				    struct sof_ipc_trace_filter_elem *elem_list,
 47				    int capacity, int *counter)
 48{
 49	if (*counter >= capacity)
 50		return -ENOMEM;
 51
 52	elem_list[*counter].key = key;
 53	elem_list[*counter].value = value;
 54	++*counter;
 55
 56	return 0;
 57}
 58
 59static int trace_filter_parse_entry(struct snd_sof_dev *sdev, const char *line,
 60				    struct sof_ipc_trace_filter_elem *elem,
 61				    int capacity, int *counter)
 62{
 63	int log_level, pipe_id, comp_id, read, ret;
 64	int len = strlen(line);
 65	int cnt = *counter;
 66	u32 uuid_id;
 67
 68	/* ignore empty content */
 69	ret = sscanf(line, " %n", &read);
 70	if (!ret && read == len)
 71		return len;
 72
 73	ret = sscanf(line, " %d %x %d %d %n", &log_level, &uuid_id, &pipe_id, &comp_id, &read);
 74	if (ret != TRACE_FILTER_ELEMENTS_PER_ENTRY || read != len) {
 75		dev_err(sdev->dev, "Invalid trace filter entry '%s'\n", line);
 76		return -EINVAL;
 77	}
 78
 79	if (uuid_id > 0) {
 80		ret = trace_filter_append_elem(sdev, SOF_IPC_TRACE_FILTER_ELEM_BY_UUID,
 81					       uuid_id, elem, capacity, &cnt);
 82		if (ret)
 83			return ret;
 84	}
 85	if (pipe_id >= 0) {
 86		ret = trace_filter_append_elem(sdev, SOF_IPC_TRACE_FILTER_ELEM_BY_PIPE,
 87					       pipe_id, elem, capacity, &cnt);
 88		if (ret)
 89			return ret;
 90	}
 91	if (comp_id >= 0) {
 92		ret = trace_filter_append_elem(sdev, SOF_IPC_TRACE_FILTER_ELEM_BY_COMP,
 93					       comp_id, elem, capacity, &cnt);
 94		if (ret)
 95			return ret;
 96	}
 97
 98	ret = trace_filter_append_elem(sdev, SOF_IPC_TRACE_FILTER_ELEM_SET_LEVEL |
 99				       SOF_IPC_TRACE_FILTER_ELEM_FIN,
100				       log_level, elem, capacity, &cnt);
101	if (ret)
102		return ret;
103
104	/* update counter only when parsing whole entry passed */
105	*counter = cnt;
106
107	return len;
108}
109
110static int trace_filter_parse(struct snd_sof_dev *sdev, char *string,
111			      int *out_elem_cnt,
112			      struct sof_ipc_trace_filter_elem **out)
113{
114	static const char entry_delimiter[] = ";";
115	char *entry = string;
116	int capacity = 0;
117	int entry_len;
118	int cnt = 0;
119
120	/*
121	 * Each entry contains at least 1, up to TRACE_FILTER_ELEMENTS_PER_ENTRY
122	 * IPC elements, depending on content. Calculate IPC elements capacity
123	 * for the input string where each element is set.
124	 */
125	while (entry) {
126		capacity += TRACE_FILTER_ELEMENTS_PER_ENTRY;
127		entry = strchr(entry + 1, entry_delimiter[0]);
128	}
129	*out = kmalloc_array(capacity, sizeof(**out), GFP_KERNEL);
130	if (!*out)
131		return -ENOMEM;
132
133	/* split input string by ';', and parse each entry separately in trace_filter_parse_entry */
134	while ((entry = strsep(&string, entry_delimiter))) {
135		entry_len = trace_filter_parse_entry(sdev, entry, *out, capacity, &cnt);
136		if (entry_len < 0) {
137			dev_err(sdev->dev,
138				"Parsing filter entry '%s' failed with %d\n",
139				entry, entry_len);
140			return -EINVAL;
141		}
142	}
143
144	*out_elem_cnt = cnt;
145
146	return 0;
147}
148
149static int ipc3_trace_update_filter(struct snd_sof_dev *sdev, int num_elems,
150				    struct sof_ipc_trace_filter_elem *elems)
151{
152	struct sof_ipc_trace_filter *msg;
153	size_t size;
154	int ret;
155
156	size = struct_size(msg, elems, num_elems);
157	if (size > SOF_IPC_MSG_MAX_SIZE)
158		return -EINVAL;
159
160	msg = kmalloc(size, GFP_KERNEL);
161	if (!msg)
162		return -ENOMEM;
163
164	msg->hdr.size = size;
165	msg->hdr.cmd = SOF_IPC_GLB_TRACE_MSG | SOF_IPC_TRACE_FILTER_UPDATE;
166	msg->elem_cnt = num_elems;
167	memcpy(&msg->elems[0], elems, num_elems * sizeof(*elems));
168
169	ret = pm_runtime_resume_and_get(sdev->dev);
170	if (ret < 0 && ret != -EACCES) {
171		dev_err(sdev->dev, "enabling device failed: %d\n", ret);
172		goto error;
173	}
174	ret = sof_ipc_tx_message_no_reply(sdev->ipc, msg, msg->hdr.size);
175	pm_runtime_put_autosuspend(sdev->dev);
176
177error:
178	kfree(msg);
179	return ret;
180}
181
182static ssize_t dfsentry_trace_filter_write(struct file *file, const char __user *from,
183					   size_t count, loff_t *ppos)
184{
185	struct snd_sof_dfsentry *dfse = file->private_data;
186	struct sof_ipc_trace_filter_elem *elems = NULL;
187	struct snd_sof_dev *sdev = dfse->sdev;
188	int num_elems;
189	char *string;
190	int ret;
191
192	if (count > TRACE_FILTER_MAX_CONFIG_STRING_LENGTH) {
193		dev_err(sdev->dev, "%s too long input, %zu > %d\n", __func__, count,
194			TRACE_FILTER_MAX_CONFIG_STRING_LENGTH);
195		return -EINVAL;
196	}
197
198	string = memdup_user_nul(from, count);
199	if (IS_ERR(string))
200		return PTR_ERR(string);
201
202	ret = trace_filter_parse(sdev, string, &num_elems, &elems);
203	if (ret < 0)
204		goto error;
205
206	if (num_elems) {
207		ret = ipc3_trace_update_filter(sdev, num_elems, elems);
208		if (ret < 0) {
209			dev_err(sdev->dev, "Filter update failed: %d\n", ret);
210			goto error;
211		}
212	}
213	ret = count;
214error:
215	kfree(string);
216	kfree(elems);
217	return ret;
218}
219
220static const struct file_operations sof_dfs_trace_filter_fops = {
221	.open = simple_open,
222	.write = dfsentry_trace_filter_write,
223	.llseek = default_llseek,
224};
225
226static int debugfs_create_trace_filter(struct snd_sof_dev *sdev)
227{
228	struct snd_sof_dfsentry *dfse;
229
230	dfse = devm_kzalloc(sdev->dev, sizeof(*dfse), GFP_KERNEL);
231	if (!dfse)
232		return -ENOMEM;
233
234	dfse->sdev = sdev;
235	dfse->type = SOF_DFSENTRY_TYPE_BUF;
236
237	debugfs_create_file("filter", 0200, sdev->debugfs_root, dfse,
238			    &sof_dfs_trace_filter_fops);
239	/* add to dfsentry list */
240	list_add(&dfse->list, &sdev->dfsentry_list);
241
242	return 0;
243}
244
245static bool sof_dtrace_set_host_offset(struct sof_dtrace_priv *priv, u32 new_offset)
246{
247	u32 host_offset = READ_ONCE(priv->host_offset);
248
249	if (host_offset != new_offset) {
250		/* This is a bit paranoid and unlikely that it is needed */
251		u32 ret = cmpxchg(&priv->host_offset, host_offset, new_offset);
252
253		if (ret == host_offset)
254			return true;
255	}
256
257	return false;
258}
259
260static size_t sof_dtrace_avail(struct snd_sof_dev *sdev,
261			       loff_t pos, size_t buffer_size)
262{
263	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
264	loff_t host_offset = READ_ONCE(priv->host_offset);
265
266	/*
267	 * If host offset is less than local pos, it means write pointer of
268	 * host DMA buffer has been wrapped. We should output the trace data
269	 * at the end of host DMA buffer at first.
270	 */
271	if (host_offset < pos)
272		return buffer_size - pos;
273
274	/* If there is available trace data now, it is unnecessary to wait. */
275	if (host_offset > pos)
276		return host_offset - pos;
277
278	return 0;
279}
280
281static size_t sof_wait_dtrace_avail(struct snd_sof_dev *sdev, loff_t pos,
282				    size_t buffer_size)
283{
284	size_t ret = sof_dtrace_avail(sdev, pos, buffer_size);
285	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
286	wait_queue_entry_t wait;
287
288	/* data immediately available */
289	if (ret)
290		return ret;
291
292	if (priv->dtrace_draining && !trace_pos_update_expected(priv)) {
293		/*
294		 * tracing has ended and all traces have been
295		 * read by client, return EOF
296		 */
297		priv->dtrace_draining = false;
298		return 0;
299	}
300
301	/* wait for available trace data from FW */
302	init_waitqueue_entry(&wait, current);
303	set_current_state(TASK_INTERRUPTIBLE);
304	add_wait_queue(&priv->trace_sleep, &wait);
305
306	if (!signal_pending(current)) {
307		/* set timeout to max value, no error code */
308		schedule_timeout(MAX_SCHEDULE_TIMEOUT);
309	}
310	remove_wait_queue(&priv->trace_sleep, &wait);
311
312	return sof_dtrace_avail(sdev, pos, buffer_size);
313}
314
315static ssize_t dfsentry_dtrace_read(struct file *file, char __user *buffer,
316				    size_t count, loff_t *ppos)
317{
318	struct snd_sof_dfsentry *dfse = file->private_data;
319	struct snd_sof_dev *sdev = dfse->sdev;
320	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
321	unsigned long rem;
322	loff_t lpos = *ppos;
323	size_t avail, buffer_size = dfse->size;
324	u64 lpos_64;
325
326	/* make sure we know about any failures on the DSP side */
327	priv->dtrace_error = false;
328
329	/* check pos and count */
330	if (lpos < 0)
331		return -EINVAL;
332	if (!count)
333		return 0;
334
335	/* check for buffer wrap and count overflow */
336	lpos_64 = lpos;
337	lpos = do_div(lpos_64, buffer_size);
338
339	/* get available count based on current host offset */
340	avail = sof_wait_dtrace_avail(sdev, lpos, buffer_size);
341	if (priv->dtrace_error) {
342		dev_err(sdev->dev, "trace IO error\n");
343		return -EIO;
344	}
345
346	/* no new trace data */
347	if (!avail)
348		return 0;
349
350	/* make sure count is <= avail */
351	if (count > avail)
352		count = avail;
353
354	/*
355	 * make sure that all trace data is available for the CPU as the trace
356	 * data buffer might be allocated from non consistent memory.
357	 * Note: snd_dma_buffer_sync() is called for normal audio playback and
358	 *	 capture streams also.
359	 */
360	snd_dma_buffer_sync(&priv->dmatb, SNDRV_DMA_SYNC_CPU);
361	/* copy available trace data to debugfs */
362	rem = copy_to_user(buffer, ((u8 *)(dfse->buf) + lpos), count);
363	if (rem)
364		return -EFAULT;
365
366	*ppos += count;
367
368	/* move debugfs reading position */
369	return count;
370}
371
372static int dfsentry_dtrace_release(struct inode *inode, struct file *file)
373{
374	struct snd_sof_dfsentry *dfse = inode->i_private;
375	struct snd_sof_dev *sdev = dfse->sdev;
376	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
377
378	/* avoid duplicate traces at next open */
379	if (priv->dtrace_state != SOF_DTRACE_ENABLED)
380		sof_dtrace_set_host_offset(priv, 0);
381
382	return 0;
383}
384
385static const struct file_operations sof_dfs_dtrace_fops = {
386	.open = simple_open,
387	.read = dfsentry_dtrace_read,
388	.llseek = default_llseek,
389	.release = dfsentry_dtrace_release,
390};
391
392static int debugfs_create_dtrace(struct snd_sof_dev *sdev)
393{
394	struct sof_dtrace_priv *priv;
395	struct snd_sof_dfsentry *dfse;
396	int ret;
397
398	if (!sdev)
399		return -EINVAL;
400
401	priv = sdev->fw_trace_data;
402
403	ret = debugfs_create_trace_filter(sdev);
404	if (ret < 0)
405		dev_warn(sdev->dev, "failed to create filter debugfs file: %d", ret);
406
407	dfse = devm_kzalloc(sdev->dev, sizeof(*dfse), GFP_KERNEL);
408	if (!dfse)
409		return -ENOMEM;
410
411	dfse->type = SOF_DFSENTRY_TYPE_BUF;
412	dfse->buf = priv->dmatb.area;
413	dfse->size = priv->dmatb.bytes;
414	dfse->sdev = sdev;
415
416	debugfs_create_file("trace", 0444, sdev->debugfs_root, dfse,
417			    &sof_dfs_dtrace_fops);
418
419	return 0;
420}
421
422static int ipc3_dtrace_enable(struct snd_sof_dev *sdev)
423{
424	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
425	struct sof_ipc_fw_ready *ready = &sdev->fw_ready;
426	struct sof_ipc_fw_version *v = &ready->version;
427	struct sof_ipc_dma_trace_params_ext params;
428	int ret;
429
430	if (!sdev->fw_trace_is_supported)
431		return 0;
432
433	if (priv->dtrace_state == SOF_DTRACE_ENABLED || !priv->dma_trace_pages)
434		return -EINVAL;
435
436	if (priv->dtrace_state == SOF_DTRACE_STOPPED)
437		goto start;
438
439	/* set IPC parameters */
440	params.hdr.cmd = SOF_IPC_GLB_TRACE_MSG;
441	/* PARAMS_EXT is only supported from ABI 3.7.0 onwards */
442	if (v->abi_version >= SOF_ABI_VER(3, 7, 0)) {
443		params.hdr.size = sizeof(struct sof_ipc_dma_trace_params_ext);
444		params.hdr.cmd |= SOF_IPC_TRACE_DMA_PARAMS_EXT;
445		params.timestamp_ns = ktime_get(); /* in nanosecond */
446	} else {
447		params.hdr.size = sizeof(struct sof_ipc_dma_trace_params);
448		params.hdr.cmd |= SOF_IPC_TRACE_DMA_PARAMS;
449	}
450	params.buffer.phy_addr = priv->dmatp.addr;
451	params.buffer.size = priv->dmatb.bytes;
452	params.buffer.pages = priv->dma_trace_pages;
453	params.stream_tag = 0;
454
455	sof_dtrace_set_host_offset(priv, 0);
456	priv->dtrace_draining = false;
457
458	ret = sof_dtrace_host_init(sdev, &priv->dmatb, &params);
459	if (ret < 0) {
460		dev_err(sdev->dev, "Host dtrace init failed: %d\n", ret);
461		return ret;
462	}
463	dev_dbg(sdev->dev, "stream_tag: %d\n", params.stream_tag);
464
465	/* send IPC to the DSP */
466	priv->dtrace_state = SOF_DTRACE_INITIALIZING;
467	ret = sof_ipc_tx_message_no_reply(sdev->ipc, &params, sizeof(params));
468	if (ret < 0) {
469		dev_err(sdev->dev, "can't set params for DMA for trace %d\n", ret);
470		goto trace_release;
471	}
472
473start:
474	priv->dtrace_state = SOF_DTRACE_ENABLED;
475
476	ret = sof_dtrace_host_trigger(sdev, SNDRV_PCM_TRIGGER_START);
477	if (ret < 0) {
478		dev_err(sdev->dev, "Host dtrace trigger start failed: %d\n", ret);
479		goto trace_release;
480	}
481
482	return 0;
483
484trace_release:
485	priv->dtrace_state = SOF_DTRACE_DISABLED;
486	sof_dtrace_host_release(sdev);
487	return ret;
488}
489
490static int ipc3_dtrace_init(struct snd_sof_dev *sdev)
491{
492	struct sof_dtrace_priv *priv;
493	int ret;
494
495	/* dtrace is only supported with SOF_IPC */
496	if (sdev->pdata->ipc_type != SOF_IPC_TYPE_3)
497		return -EOPNOTSUPP;
498
499	if (sdev->fw_trace_data) {
500		dev_err(sdev->dev, "fw_trace_data has been already allocated\n");
501		return -EBUSY;
502	}
503
504	priv = devm_kzalloc(sdev->dev, sizeof(*priv), GFP_KERNEL);
505	if (!priv)
506		return -ENOMEM;
507
508	sdev->fw_trace_data = priv;
509
510	/* set false before start initialization */
511	priv->dtrace_state = SOF_DTRACE_DISABLED;
512
513	/* allocate trace page table buffer */
514	ret = snd_dma_alloc_pages(SNDRV_DMA_TYPE_DEV, sdev->dev,
515				  PAGE_SIZE, &priv->dmatp);
516	if (ret < 0) {
517		dev_err(sdev->dev, "can't alloc page table for trace %d\n", ret);
518		return ret;
519	}
520
521	/* allocate trace data buffer */
522	ret = snd_dma_alloc_dir_pages(SNDRV_DMA_TYPE_DEV_SG, sdev->dev,
523				      DMA_FROM_DEVICE, DMA_BUF_SIZE_FOR_TRACE,
524				      &priv->dmatb);
525	if (ret < 0) {
526		dev_err(sdev->dev, "can't alloc buffer for trace %d\n", ret);
527		goto page_err;
528	}
529
530	/* create compressed page table for audio firmware */
531	ret = snd_sof_create_page_table(sdev->dev, &priv->dmatb,
532					priv->dmatp.area, priv->dmatb.bytes);
533	if (ret < 0)
534		goto table_err;
535
536	priv->dma_trace_pages = ret;
537	dev_dbg(sdev->dev, "dma_trace_pages: %d\n", priv->dma_trace_pages);
538
539	if (sdev->first_boot) {
540		ret = debugfs_create_dtrace(sdev);
541		if (ret < 0)
542			goto table_err;
543	}
544
545	init_waitqueue_head(&priv->trace_sleep);
546
547	ret = ipc3_dtrace_enable(sdev);
548	if (ret < 0)
549		goto table_err;
550
551	return 0;
552table_err:
553	priv->dma_trace_pages = 0;
554	snd_dma_free_pages(&priv->dmatb);
555page_err:
556	snd_dma_free_pages(&priv->dmatp);
557	return ret;
558}
559
560int ipc3_dtrace_posn_update(struct snd_sof_dev *sdev,
561			    struct sof_ipc_dma_trace_posn *posn)
562{
563	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
564
565	if (!sdev->fw_trace_is_supported)
566		return 0;
567
568	if (trace_pos_update_expected(priv) &&
569	    sof_dtrace_set_host_offset(priv, posn->host_offset))
570		wake_up(&priv->trace_sleep);
571
572	if (posn->overflow != 0)
573		dev_err(sdev->dev,
574			"DSP trace buffer overflow %u bytes. Total messages %d\n",
575			posn->overflow, posn->messages);
576
577	return 0;
578}
579
580/* an error has occurred within the DSP that prevents further trace */
581static void ipc3_dtrace_fw_crashed(struct snd_sof_dev *sdev)
582{
583	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
584
585	if (priv->dtrace_state == SOF_DTRACE_ENABLED) {
586		priv->dtrace_error = true;
587		wake_up(&priv->trace_sleep);
588	}
589}
590
591static void ipc3_dtrace_release(struct snd_sof_dev *sdev, bool only_stop)
592{
593	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
594	struct sof_ipc_fw_ready *ready = &sdev->fw_ready;
595	struct sof_ipc_fw_version *v = &ready->version;
596	struct sof_ipc_cmd_hdr hdr;
597	int ret;
598
599	if (!sdev->fw_trace_is_supported || priv->dtrace_state == SOF_DTRACE_DISABLED)
600		return;
601
602	ret = sof_dtrace_host_trigger(sdev, SNDRV_PCM_TRIGGER_STOP);
603	if (ret < 0)
604		dev_err(sdev->dev, "Host dtrace trigger stop failed: %d\n", ret);
605	priv->dtrace_state = SOF_DTRACE_STOPPED;
606
607	/*
608	 * stop and free trace DMA in the DSP. TRACE_DMA_FREE is only supported from
609	 * ABI 3.20.0 onwards
610	 */
611	if (v->abi_version >= SOF_ABI_VER(3, 20, 0)) {
612		hdr.size = sizeof(hdr);
613		hdr.cmd = SOF_IPC_GLB_TRACE_MSG | SOF_IPC_TRACE_DMA_FREE;
614
615		ret = sof_ipc_tx_message_no_reply(sdev->ipc, &hdr, hdr.size);
616		if (ret < 0)
617			dev_err(sdev->dev, "DMA_TRACE_FREE failed with error: %d\n", ret);
618	}
619
620	if (only_stop)
621		goto out;
622
623	ret = sof_dtrace_host_release(sdev);
624	if (ret < 0)
625		dev_err(sdev->dev, "Host dtrace release failed %d\n", ret);
626
627	priv->dtrace_state = SOF_DTRACE_DISABLED;
628
629out:
630	priv->dtrace_draining = true;
631	wake_up(&priv->trace_sleep);
632}
633
634static void ipc3_dtrace_suspend(struct snd_sof_dev *sdev, pm_message_t pm_state)
635{
636	ipc3_dtrace_release(sdev, pm_state.event == SOF_DSP_PM_D0);
637}
638
639static int ipc3_dtrace_resume(struct snd_sof_dev *sdev)
640{
641	return ipc3_dtrace_enable(sdev);
642}
643
644static void ipc3_dtrace_free(struct snd_sof_dev *sdev)
645{
646	struct sof_dtrace_priv *priv = sdev->fw_trace_data;
647
648	/* release trace */
649	ipc3_dtrace_release(sdev, false);
650
651	if (priv->dma_trace_pages) {
652		snd_dma_free_pages(&priv->dmatb);
653		snd_dma_free_pages(&priv->dmatp);
654		priv->dma_trace_pages = 0;
655	}
656}
657
658const struct sof_ipc_fw_tracing_ops ipc3_dtrace_ops = {
659	.init = ipc3_dtrace_init,
660	.free = ipc3_dtrace_free,
661	.fw_crashed = ipc3_dtrace_fw_crashed,
662	.suspend = ipc3_dtrace_suspend,
663	.resume = ipc3_dtrace_resume,
664};