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