OpenE2K/linux
6
0
Fork 0
Code Issues Pull Requests Releases Wiki Activity
9860118b58
linux/sound/firewire/amdtp-stream-trace.h

111 lines
3.2 KiB
C
Raw Normal View History

ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
/*
* amdtp-stream-trace.h - tracepoint definitions to dump a part of packet data
*
* Copyright (c) 2016 Takashi Sakamoto
* Licensed under the terms of the GNU General Public License, version 2.
*/
#undef TRACE_SYSTEM
#define TRACE_SYSTEM snd_firewire_lib
#if !defined(_AMDTP_STREAM_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
#define _AMDTP_STREAM_TRACE_H
#include <linux/tracepoint.h>
TRACE_EVENT(in_packet,
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
TP_PROTO(const struct amdtp_stream *s, u32 cycles, u32 cip_header[2], unsigned int payload_quadlets, unsigned int index),
TP_ARGS(s, cycles, cip_header, payload_quadlets, index),
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
TP_STRUCT__entry(
__field(unsigned int, second)
__field(unsigned int, cycle)
__field(int, channel)
__field(int, src)
__field(int, dest)
__field(u32, cip_header0)
__field(u32, cip_header1)
__field(unsigned int, payload_quadlets)
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
__field(unsigned int, packet_index)
ALSA: firewire-lib: change a member of event structure to suppress sparse wanings to bool type Commit a9c4284bf5a9 ("ALSA: firewire-lib: add context information to tracepoints") adds new members to tracepoint events of this module, to represent context information. One of the members is bool type and this causes sparse warnings. 16:1: warning: expression using sizeof bool 60:1: warning: expression using sizeof bool 16:1: warning: odd constant _Bool cast (ffffffffffffffff becomes 1) 60:1: warning: odd constant _Bool cast (ffffffffffffffff becomes 1) This commit suppresses the warnings, by changing type of the member to 'unsigned int'. Additionally, this commit applies '!!' idiom to get 0/1 from 'in_interrupt()'. Fixes: a9c4284bf5a9 ("ALSA: firewire-lib: add context information to tracepoints") Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-18 15:27:43 +02:00
__field(unsigned int, irq)
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
__field(unsigned int, index)
),
TP_fast_assign(
__entry->second = cycles / CYCLES_PER_SECOND;
__entry->cycle = cycles % CYCLES_PER_SECOND;
__entry->channel = s->context->channel;
__entry->src = fw_parent_device(s->unit)->node_id;
__entry->dest = fw_parent_device(s->unit)->card->node_id;
__entry->cip_header0 = cip_header[0];
__entry->cip_header1 = cip_header[1];
__entry->payload_quadlets = payload_quadlets;
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
__entry->packet_index = s->packet_index;
ALSA: firewire-lib: change a member of event structure to suppress sparse wanings to bool type Commit a9c4284bf5a9 ("ALSA: firewire-lib: add context information to tracepoints") adds new members to tracepoint events of this module, to represent context information. One of the members is bool type and this causes sparse warnings. 16:1: warning: expression using sizeof bool 60:1: warning: expression using sizeof bool 16:1: warning: odd constant _Bool cast (ffffffffffffffff becomes 1) 60:1: warning: odd constant _Bool cast (ffffffffffffffff becomes 1) This commit suppresses the warnings, by changing type of the member to 'unsigned int'. Additionally, this commit applies '!!' idiom to get 0/1 from 'in_interrupt()'. Fixes: a9c4284bf5a9 ("ALSA: firewire-lib: add context information to tracepoints") Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-18 15:27:43 +02:00
__entry->irq = !!in_interrupt();
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
__entry->index = index;
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
),
TP_printk(
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
"%02u %04u %04x %04x %02d %08x %08x %03u %02u %01u %02u",
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
__entry->second,
__entry->cycle,
__entry->src,
__entry->dest,
__entry->channel,
__entry->cip_header0,
__entry->cip_header1,
__entry->payload_quadlets,
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
__entry->packet_index,
__entry->irq,
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
__entry->index)
);
TRACE_EVENT(out_packet,
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
TP_PROTO(const struct amdtp_stream *s, u32 cycles, __be32 *cip_header, unsigned int payload_length, unsigned int index),
TP_ARGS(s, cycles, cip_header, payload_length, index),
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
TP_STRUCT__entry(
__field(unsigned int, second)
__field(unsigned int, cycle)
__field(int, channel)
__field(int, src)
__field(int, dest)
__field(u32, cip_header0)
__field(u32, cip_header1)
__field(unsigned int, payload_quadlets)
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
__field(unsigned int, packet_index)
ALSA: firewire-lib: change a member of event structure to suppress sparse wanings to bool type Commit a9c4284bf5a9 ("ALSA: firewire-lib: add context information to tracepoints") adds new members to tracepoint events of this module, to represent context information. One of the members is bool type and this causes sparse warnings. 16:1: warning: expression using sizeof bool 60:1: warning: expression using sizeof bool 16:1: warning: odd constant _Bool cast (ffffffffffffffff becomes 1) 60:1: warning: odd constant _Bool cast (ffffffffffffffff becomes 1) This commit suppresses the warnings, by changing type of the member to 'unsigned int'. Additionally, this commit applies '!!' idiom to get 0/1 from 'in_interrupt()'. Fixes: a9c4284bf5a9 ("ALSA: firewire-lib: add context information to tracepoints") Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-18 15:27:43 +02:00
__field(unsigned int, irq)
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
__field(unsigned int, index)
),
TP_fast_assign(
__entry->second = cycles / CYCLES_PER_SECOND;
__entry->cycle = cycles % CYCLES_PER_SECOND;
__entry->channel = s->context->channel;
__entry->src = fw_parent_device(s->unit)->card->node_id;
__entry->dest = fw_parent_device(s->unit)->node_id;
__entry->cip_header0 = be32_to_cpu(cip_header[0]);
__entry->cip_header1 = be32_to_cpu(cip_header[1]);
__entry->payload_quadlets = payload_length / 4;
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
__entry->packet_index = s->packet_index;
ALSA: firewire-lib: change a member of event structure to suppress sparse wanings to bool type Commit a9c4284bf5a9 ("ALSA: firewire-lib: add context information to tracepoints") adds new members to tracepoint events of this module, to represent context information. One of the members is bool type and this causes sparse warnings. 16:1: warning: expression using sizeof bool 60:1: warning: expression using sizeof bool 16:1: warning: odd constant _Bool cast (ffffffffffffffff becomes 1) 60:1: warning: odd constant _Bool cast (ffffffffffffffff becomes 1) This commit suppresses the warnings, by changing type of the member to 'unsigned int'. Additionally, this commit applies '!!' idiom to get 0/1 from 'in_interrupt()'. Fixes: a9c4284bf5a9 ("ALSA: firewire-lib: add context information to tracepoints") Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-18 15:27:43 +02:00
__entry->irq = !!in_interrupt();
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
__entry->index = index;
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
),
TP_printk(
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
"%02u %04u %04x %04x %02d %08x %08x %03u %02u %01u %02u",
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
__entry->second,
__entry->cycle,
__entry->src,
__entry->dest,
__entry->channel,
__entry->cip_header0,
__entry->cip_header1,
__entry->payload_quadlets,
ALSA: firewire-lib: add context information to tracepoints In current implementation, packet processing is done in both of software IRQ contexts of IR/IT contexts and process contexts. This is usual interrupt handling of IR/IT context for 1394 OHCI. (in hardware IRQ context) irq_handler() (drivers/firewire/ohci.c) ->tasklet_schedule() (in software IRQ context) handle_it_packet() or handle_ir_packet_per_buffer() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() However, we have another chance for packet processing. It's done in PCM frame handling via ALSA PCM interfaces. (in process context) ioctl(i.e. SNDRV_PCM_IOCTL_HWSYNC) ->snd_pcm_hwsync() (sound/core/pcm_native.c) ->snd_pcm_update_hw_ptr() (sound/core/pcm_lib.c) ->snd_pcm_update_hw_ptr0() ->struct snd_pcm_ops.pointer() = amdtp_stream_pcm_pointer() ->fw_iso_context_flush_completions() (drivers/firewire/core-iso.c) ->struct fw_card_driver.flush_iso_completions() = ohci_flush_iso_completions() (drivers/firewire/ohci.c) ->flush_iso_completions() ->struct fw_iso_context.callback.sc() = out_stream_callback() or in_stream_callback() This design is for a better granularity of PCM pointer. When ioctl(2) is executed with some commands for ALSA PCM interface, queued packets are handled at first. Then, the latest number of handled PCM frames is reported. The number can represent PCM frames transferred in most near isochronous cycle. Current tracepoints include no information to distinguish running contexts. When tracing the interval of software IRQ context, this is not good. This commit adds more information for current context. Additionally, the index of packet processed in one context is added in a case that packet processing is executed in continuous context of the same kind, As a result, the output includes 11 fields with additional two fields to commit 0c95c1d6197f ("ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data"): 17131.9186: out_packet: 07 7494 ffc0 ffc1 00 000700c0 9001a496 058 45 1 13 17131.9186: out_packet: 07 7495 ffc0 ffc1 00 000700c8 9001ba00 058 46 1 14 17131.9186: out_packet: 07 7496 ffc0 ffc1 00 000700d0 9001ffff 002 47 1 15 17131.9189: out_packet: 07 7497 ffc0 ffc1 00 000700d0 9001d36a 058 00 0 00 17131.9189: out_packet: 07 7498 ffc0 ffc1 00 000700d8 9001e8d4 058 01 0 01 17131.9189: out_packet: 07 7499 ffc0 ffc1 00 000700e0 9001023e 058 02 0 00 17131.9206: in_packet: 07 7447 ffc1 ffc0 01 3f070072 9001783d 058 32 1 00 17131.9206: in_packet: 07 7448 ffc1 ffc0 01 3f070072 90ffffff 002 33 1 01 17131.9206: in_packet: 07 7449 ffc1 ffc0 01 3f07007a 900191a8 058 34 1 02 (Here, some common fields are omitted so that a line is within 80 characters.) The legend is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - The ID of node as destination (hex) - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module - 0 in process context, 1 in IRQ context - The index of packet processed in the context Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-11 00:33:27 +02:00
__entry->packet_index,
__entry->irq,
ALSA: firewire-lib: add tracepoints to dump a part of isochronous packet data When audio and music units have some quirks in their sequence of packet, it's really hard for non-owners to identify the quirks. Although developers need dumps for sequence of packets, it's difficult for users who have no knowledges and no equipments for this purpose. This commit adds tracepoints for this situation. When users encounter the issue, they can dump a part of packet data via Linux tracing framework as long as using drivers in ALSA firewire stack. Additionally, tracepoints for outgoing packets will be our help to check and debug packet processing of ALSA firewire stack. This commit newly adds 'snd_firewire_lib' subsystem with 'in_packet' and 'out_packet' events. In the events, some attributes of packets and the index of packet managed by this module are recorded per packet. This is an usage: $ trace-cmd record -e snd_firewire_lib:out_packet \ -e snd_firewire_lib:in_packet /sys/kernel/tracing/events/snd_firewire_lib/out_packet/filter /sys/kernel/tracing/events/snd_firewire_lib/in_packet/filter Hit Ctrl^C to stop recording ^C $ trace-cmd report trace.dat ... 23647.033934: in_packet: 01 4073 ffc0 ffc1 00 000f0040 9001b2d1 122 44 23647.033936: in_packet: 01 4074 ffc0 ffc1 00 000f0048 9001c83b 122 45 23647.033937: in_packet: 01 4075 ffc0 ffc1 00 000f0050 9001ffff 002 46 23647.033938: in_packet: 01 4076 ffc0 ffc1 00 000f0050 9001e1a6 122 47 23647.035426: out_packet: 01 4123 ffc1 ffc0 01 010f00d0 9001fb40 122 17 23647.035428: out_packet: 01 4124 ffc1 ffc0 01 010f00d8 9001ffff 002 18 23647.035429: out_packet: 01 4125 ffc1 ffc0 01 010f00d8 900114aa 122 19 23647.035430: out_packet: 01 4126 ffc1 ffc0 01 010f00e0 90012a15 122 20 (Here, some common fields are omitted so that a line to be within 80 characters.) ... One line represent one packet. The legend for the last nine fields is: - The second of cycle scheduled for the packet - The count of cycle scheduled for the packet - The ID of node as source (hex) - Some devices transfer packets with invalid source node ID in their CIP header. - The ID of node as destination (hex) - The value is not in CIP header of packets. - The value of isochronous channel - The first quadlet of CIP header (hex) - The second quadlet of CIP header (hex) - The number of included quadlets - The index of packet in a buffer maintained by this module This is an example to parse these lines from text file by Python3 script: \#!/usr/bin/env python3 import sys def parse_ts(second, cycle, syt): offset = syt & 0xfff syt >>= 12 if cycle & 0x0f > syt: cycle += 0x10 cycle &= 0x1ff0 cycle |= syt second += cycle // 8000 cycle %= 8000 # In CYCLE_TIMER of 1394 OHCI, second is represented in 8 bit. second %= 128 return (second, cycle, offset) def calc_ts(second, cycle, offset): ts = offset ts += cycle * 3072 # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. ts += (second % 8) * 8000 * 3072 return ts def subtract_ts(minuend, subtrahend): # In DMA descriptor of 1394 OHCI, second is represented in 3 bit. if minuend < subtrahend: minuend += 8 * 8000 * 3072 return minuend - subtrahend if len(sys.argv) != 2: print('At least, one argument is required for packet dump.') sys.exit() filename = sys.argv[1] data = [] prev = 0 with open(filename, 'r') as f: for line in f: pos = line.find('packet:') if pos < 0: continue pos += len('packet:') line = line[pos:].strip() fields = line.split(' ') datum = [] datum.append(fields[8]) syt = int(fields[6][4:], 16) # Empty packet in IEC 61883-1, or NODATA in IEC 61883-6 if syt == 0xffff: data_blocks = 0 else: payload_size = int(fields[7], 10) data_block_size = int(fields[5][2:4], 16) data_blocks = (payload_size - 2) / data_block_size datum.append(data_blocks) second = int(fields[0], 10) cycle = int(fields[1], 10) start = (second << 25) | (cycle << 12) datum.append('0x{0:08x}'.format(start)) start = calc_ts(second, cycle, 0) datum.append("0x" + fields[5]) datum.append("0x" + fields[6]) if syt == 0xffff: second = 0 cycle = 0 tick = 0 else: second, cycle, tick = parse_ts(second, cycle, syt) ts = calc_ts(second, cycle, tick) datum.append(start) datum.append(ts) if ts == 0: datum.append(0) datum.append(0) else: # Usual case, or a case over 8 seconds. if ts > start or start > 7 * 8000 * 3072: datum.append(subtract_ts(ts, start)) if ts > prev or start > 7 * 8000 * 3072: gap = subtract_ts(ts, prev) datum.append(gap) else: datum.append('backward') else: datum.append('invalid') prev = ts data.append(datum) sys.exit() The data variable includes array with these elements: - The index of the packet - The number of data blocks in the packet - The value of cycle count (hex) - The value of CIP header 1 (hex) - The value of CIP header 2 (hex) - The value of cycle count (tick) - The value of calculated presentation timestamp (tick) - The offset between the cycle count and presentation timestamp - The elapsed ticks from the previous presentation timestamp Signed-off-by: Takashi Sakamoto <o-takashi@sakamocchi.jp> Signed-off-by: Takashi Iwai <tiwai@suse.de>
2016-05-09 14:12:46 +02:00
__entry->index)
);
#endif
#undef TRACE_INCLUDE_PATH
#define TRACE_INCLUDE_PATH .
#undef TRACE_INCLUDE_FILE
#define TRACE_INCLUDE_FILE amdtp-stream-trace
#include <trace/define_trace.h>
Reference in New Issue Copy Permalink