[ltt-dev] ltt

* [ltt-dev] ltt - no traces logged using lttctl
@ 2009-03-09 17:26 francois arsenault
  2009-03-09 17:26 ` francois arsenault
                   ` (2 more replies)
  0 siblings, 3 replies; 8+ messages in thread
From: francois arsenault @ 2009-03-09 17:26 UTC (permalink / raw)

Hello to all,

We are trying to use the ltt for debugging a problem on our hardware and no data is logged in the trace.
Our Hardware:
- ppc405gpr
- linux 2.6 (Linux version 2.6.26.8-00004) - from Denx

We have done the following steps for the ltt installation:
- Download "patch-2.6.26-rc8-0.10-pre56" from http://ltt.polymtl.ca
- installed the patch (one error on the "kernel/printk.c" file)
- In the kernel menuconfig, select all related ltt options (see the .config file attached)
- make / make modules_install
- Cross compile for the ppc405 the "ltt-control" (wget http://ltt.polymtl.ca/files/lttng/ltt-control-0.48-27022008.tar.gz)

We are using the following commands on the target to start the traces:
mkdir /mnt/debugfs
echo "debugfs         /mnt/debugfs    debugfs rw              0       0"  >> /etc/fstab
mount /mnt/debugfs

#Start Trace
lttctl -n trace -b

lttd -c /mnt/debugfs/ltt/trace -t /mnt/tmpfs/traceout1 -d

#Stop Trace
lttctl -n trace -R

Question: we are executing the "lttctl -n trace -b" command, the "/mnt/debugfs/ltt" content is always zero i.e.:
# ls -alR /mnt/debugfs/ltt
/mnt/debugfs/ltt:
drwxr-xr-x    3 0        0               0 Jan  1 00:00 .
drwxr-xr-x    6 0        0               0 Jan  1 00:00 ..
drwxr-xr-x    3 0        0               0 Jan  1 00:17 trace

/mnt/debugfs/ltt/trace:
drwxr-xr-x    3 0        0               0 Jan  1 00:17 .
drwxr-xr-x    3 0        0               0 Jan  1 00:00 ..
-r--------    1 0        0               0 Jan  1 00:17 compact_0
drwxr-xr-x    2 0        0               0 Jan  1 00:17 control
-r--------    1 0        0               0 Jan  1 00:17 cpu_0

/mnt/debugfs/ltt/trace/control:
drwxr-xr-x    2 0        0               0 Jan  1 00:17 .
drwxr-xr-x    3 0        0               0 Jan  1 00:17 ..
-r--------    1 0        0               0 Jan  1 00:17 facilities_0
-r--------    1 0        0               0 Jan  1 00:17 interrupts_0
-r--------    1 0        0               0 Jan  1 00:17 modules_0
-r--------    1 0        0               0 Jan  1 00:17 network_0
-r--------    1 0        0               0 Jan  1 00:17 processes_0

It seems that the kernel doesn't send the "trace_mark" to the application. How can I fix this or debug it?

Thanks,
Francois.

Attached,
- kernel .config

-The following are dmesg and cat /proc/ltt dump:

=========== dmesg =================
Using SMUS4000 machine description
Linux version 2.6.26.8-00004-gbb42807-dirty (franky at franky-desktop) (gcc version 4.2.2) #13 Mon Mar 9 11:20:47 EDT 2009
Found initrd at 0xc3c91000:0xc3ebc0a7
Found legacy serial port 0 for /plb/opb/serial at ef600300
  mem=ef600300, taddr=ef600300, irq=0, clk=11250112, speed=115200
Found legacy serial port 1 for /plb/opb/serial at ef600400
  mem=ef600400, taddr=ef600400, irq=0, clk=11250112, speed=115200
console [udbg0] enabled
Entering add_active_range(0, 0, 16384) 0 entries of 256 used
Top of RAM: 0x4000000, Total RAM: 0x4000000
Memory hole size: 0MB
Zone PFN ranges:
  DMA             0 ->    16384
  Normal      16384 ->    16384
Movable zone start PFN for each node
early_node_map[1] active PFN ranges
    0:        0 ->    16384
On node 0 totalpages: 16384
  DMA zone: 128 pages used for memmap
  DMA zone: 0 pages reserved
  DMA zone: 16256 pages, LIFO batch:3
  Normal zone: 0 pages used for memmap
  Movable zone: 0 pages used for memmap
Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
Kernel command line: console=ttyS1,115200 root=/dev/ram rw ip=10.0.102.247:10.0.102.71:10.0.102.71:255.255.255.0:ep405:eth0
init=./linuxrc
UIC0 (32 IRQ sources) at DCR 0xc0
PID hash table entries: 256 (order: 8, 1024 bytes)
time_init: decrementer frequency = 360.003600 MHz
time_init: processor frequency   = 360.003600 MHz
clocksource: timebase mult[b1c6a8] shift[22] registered
clockevent: decrementer mult[5c29] shift[16] cpu[0]
Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
Memory: 59552k/65536k available (2860k kernel code, 5924k reserved, 108k data, 125k bss, 140k init)
SLUB: Genslabs=10, HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
Calibrating delay loop... 718.84 BogoMIPS (lpj=1437696)
Mount-cache hash table entries: 512
net_namespace: 192 bytes
NET: Registered protocol family 16
PCI: Probing PCI hardware
NET: Registered protocol family 2
IP route cache hash table entries: 1024 (order: 0, 4096 bytes)
TCP established hash table entries: 2048 (order: 2, 16384 bytes)
TCP bind hash table entries: 2048 (order: 1, 8192 bytes)
TCP: Hash tables configured (established 2048 bind 2048)
TCP reno registered
NET: Registered protocol family 1
checking if image is initramfs...it isn't (no cpio magic); looks like an initrd
Freeing initrd memory: 2220k freed
JFFS2 version 2.2. (NAND) ?? 2001-2006 Red Hat, Inc.
msgmni has been set to 120
io scheduler noop registered
io scheduler anticipatory registered (default)
io scheduler deadline registered
io scheduler cfq registered
Synthetic TSC timer will fire each 741 jiffies.
LTT : ltt-heartbeat init
LTT : ltt-heartbeat init
Requested number of bits 11
Available number of bits 14
Heartbeat timer will fire each 88 jiffies.
Compact TSC init : truncate 8 lsb, cutoff 3 msb.
LTT : ltt-relay init
ltt-control init
LTT : State dump init
Data shifted from 24 bits
3 bits used for event IDs, 8 available for data.
Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled
serial8250.0: ttyS0 at MMIO 0xef600300 (irq = 16) is a 16550A
serial8250.0: ttyS1 at MMIO 0xef600400 (irq = 17) is a 16550A
console handover: boot [udbg0] -> real [ttyS1]
ef600300.serial: ttyS0 at MMIO 0xef600300 (irq = 16) is a 16550A
ef600400.serial: ttyS1 at MMIO 0xef600400 (irq = 17) is a 16550A
brd: module loaded
PPC 4xx OCP EMAC driver, version 3.54
MAL v1 /plb/mcmal, 1 TX channels, 1 RX channels
eth0: EMAC-0 /plb/opb/ethernet at ef600800, MAC 00:40:fd:01:ef:8e
eth0: found Generic MII PHY (0x18)
init_smu_mtd: chip probing count 0
SMU-0: Found 2 x16 devices at 0x0 in 32-bit bank
 Amd/Fujitsu Extended Query Table at 0x0040
SMU-0: CFI does not contain boot bank location. Assuming top.
number of CFI chips: 1
cfi_cmdset_0002: Disabling erase-suspend-program due to code brokenness.
init_smu_mtd: bank 1, name: SMU-0, size: 33554432 bytes
init_smu_mtd: 0 command line partitions on bank 0
SMU flash bank 0: Using static image bank1 partition definition
Creating 5 MTD partitions on "ppc4xx-nor":
0x00000000-0x01dc0000 : "flash file System"
0x01dc0000-0x01f80000 : "buf"
0x01f80000-0x01fa0000 : "env2"
mtd: partition "env2" doesn't end on an erase block -- force read-only
0x01fa0000-0x01fc0000 : "env1"
mtd: partition "env1" doesn't start on an erase block boundary -- force read-only
0x01fc0000-0x02000000 : "u-boot"
TCP cubic registered
NET: Registered protocol family 17
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
eth0: link is down
IP-Config: Complete:
     device=eth0, addr=10.0.102.247, mask=255.255.255.0, gw=10.0.102.71,
     host=ep405, domain=, nis-domain=(none),
     bootserver=10.0.102.71, rootserver=10.0.102.71, rootpath=
RAMDISK: Compressed image found at block 0
VFS: Mounted root (ext2 filesystem).
Freeing unused kernel memory: 140k init
eth0: link is up, 100 FDX, pause enabled
vxworksStubs_class_init.77: Module loaded
sat_mod: module license 'unspecified' taints kernel.
sat_init_module for sat0 net driver
sat_init_module.618: Symb: semBCreate, value: 0xc7083d94
SMUS4000 fpga0 FOUND!!!
sat_dev_interrupt_map.419: fpga0_sign_virt_irq_nbr: 0x19
sat_dev_interrupt_map.420: fpga1_sof_virt_irq_nbr: 0x1a
sat_dev_interrupt_map.432: i2c FOUND
sat_dev_interrupt_map.434: i2c_virt_irq_nbr: 0x1b
SMUF_init_module: Calling SMUF_getVirtualAddress
SATevfm_Init.363: init module
SATevfm_Init.375: init module OK
FLINK_init_module: Registering FLINK device<4>Loading SMU FPGA Programming driver version 1.0 Mar  9 2009 11:21:15
fpga_prog: got major number 254, minor 0
ltt-control ltt_control_input
ltt_control : trace trace
Creating trace trace
ltt-control ltt_control_input
ltt_control : trace trace
Start tracing trace
Data shifted from 24 bits
3 bits used for event IDs, 8 available for data.
LTT : ltt-heartbeat trigger
LTT : ltt-heartbeat start
LTT state dump begin
LTT state dump thread start
LTT state dump end
ltt-control ltt_control_input
ltt_control : trace trace
Stop tracing trace
LTT : ltt-heartbeat trigger
LTT : ltt-heartbeat stop
ltt-control ltt_control_input
ltt_control : trace trace
Destroying trace trace

=========== cat /proc/ltt =================
cat /proc/ltt
marker: kernel_arch_syscall_entry format: "syscall_id %d ip #p%ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_syscall_exit format: "ret %ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_ipc_call format: "call %u first %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_kthread_create format: "pid %ld fn %p" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_trap_entry format: "trap_id %ld ip #p%ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_trap_exit format: " " state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_trap_entry format: "trap_id %ld ip #p%ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_trap_exit format: " " state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_trap_entry format: "trap_id %ld ip #p%ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_trap_exit format: " " state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_trap_entry format: "trap_id %ld ip #p%ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_arch_trap_exit format: " " state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_sched_try_wakeup format: "pid %d state %ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: internal_kernel_sched_schedule format: "prev %p next %p" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_sched_wakeup_new_task format: "pid %d state %ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_process_fork format: "parent_pid %d child_pid %d child_tgid %d" state: 0 call: 0xc0055bf0 probe multi : 0x000
00000
marker: kernel_printk format: "ip %p" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_process_free format: "pid %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_process_wait format: "pid %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_process_exit format: "pid %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_timer_itimer_set format: "which %d interval_sec %ld interval_usec %ld value_sec %ld value_usec %ld" state: 0
call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_timer_itimer_expired format: "pid %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_softirq_raise format: "softirq_id %u" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: statedump_softirq_vec format: "id %d address %p symbol %s" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_tasklet_high_entry format: "func %p data %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_tasklet_high_exit format: "func %p data %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_tasklet_low_entry format: "func %p data %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_tasklet_low_exit format: "func %p data %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_softirq_entry format: "softirq_id %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_softirq_exit format: "softirq_id %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_timer_set format: "expires %lu function %p data %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_timer_timeout format: "pid %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_timer_update_time format: "jiffies #8u%llu xtime_sec %ld xtime_nsec %ld walltomonotonic_sec %ld walltomonoton
ic_nsec %ld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_send_signal format: "pid %d signal %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_kthread_stop format: "pid %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_kthread_stop_ret format: "ret %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_module_free format: "name %s" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_module_load format: "name %s" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: list_module format: "name %s state %d refcount %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_irq_entry format: "irq_id %u kernel_mode %u" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_irq_exit format: " " state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: core_marker_format format: "name %s format %s" state: 1 call: 0xc0055bf0 probe multi : 0x00000000
marker: core_marker_format format: "name %s format %s" state: 1 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_filemap_wait_start format: "pfn %lu bit_nr %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_filemap_wait_end format: "pfn %lu bit_nr %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_page_free format: "order %u pfn %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_page_free format: "order %u pfn %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_page_alloc format: "order %u pfn %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_handle_fault_entry format: "address %lu ip #p%ld write_access %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000
000
marker: mm_swap_in format: "pfn %lu filp %p offset %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_handle_fault_exit format: " " state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_swap_out format: "pfn %lu filp %p offset %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: statedump_swap_files format: "filp %p vfsmount %p dname %s" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_swap_file_close format: "filp %p" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: mm_swap_file_open format: "filp %p filename %s" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_close format: "fd %u" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_open format: "fd %d filename %s" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_writev format: "fd %lu vlen %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_lseek format: "fd %u offset %ld origin %u" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_llseek format: "fd %u offset %llu origin %u" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_read format: "fd %u count %zu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_write format: "fd %u count %zu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_pread64 format: "fd %u count %zu pos %llu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_pwrite64 format: "fd %u count %zu pos %llu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_readv format: "fd %lu vlen %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_exec format: "filename %s" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_ioctl format: "fd %u cmd %u arg %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_pollfd format: "fd %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_select format: "fd %d timeout #8d%lld" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_buffer_wait_start format: "bh %p" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: fs_buffer_wait_end format: "bh %p" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: ipc_msg_create format: "id %ld flags %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: ipc_sem_create format: "id %ld flags %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: ipc_shm_create format: "id %ld flags %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: core_heartbeat_32 format: " " state: 1 call: 0xc0054b40 probe multi : 0x00000000
marker: core_heartbeat_64 format: "timestamp #8u%llu" state: 1 call: 0xc0055bf0 probe multi : 0x00000000
marker: list_process_state format: "pid %d parent_pid %d name %s type %d mode %d submode %d status %d tgid %d" state: 0 call
: 0xc0055bf0 probe multi : 0x00000000
marker: list_file_descriptor format: "filename %s pid %d fd %u" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: list_vm_map format: "pid %d start %lu end %lu flags %lu pgoff %lu inode %lu" state: 0 call: 0xc0055bf0 probe multi :
 0x00000000
marker: list_interrupt format: "name %s action %s irq_id %u" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: list_network_ipv4_interface format: "name %s address #4u%lu up %d" state: 0 call: 0xc0055bf0 probe multi : 0x0000000
0
marker: list_network_ip_interface format: "name %s address #4u%lu up %d" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: list_statedump_end format: " " state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: core_marker_id format: "name %s id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" state: 1
 call: 0xc0055bf0 probe multi : 0x00000000
marker: core_marker_format format: "name %s format %s" state: 1 call: 0xc0055bf0 probe multi : 0x00000000
marker: core_marker_id format: "name %s id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" state: 1
 call: 0xc0055bf0 probe multi : 0x00000000
marker: core_marker_id format: "name %s id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" state: 1
 call: 0xc0055bf0 probe multi : 0x00000000
marker: core_marker_id format: "name %s id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" state: 1
 call: 0xc0055bf0 probe multi : 0x00000000
marker: kernel_sched_schedule format: "prev_pid %d next_pid %d prev_state %ld" state: 0 call: 0xc0055bf0 probe multi : 0x000
00000
marker: net_socket_recvmsg format: "sock %p family %d type %d protocol %d size %zu" state: 0 call: 0xc0055bf0 probe multi :
0x00000000
marker: net_socket_sendmsg format: "sock %p family %d type %d protocol %d size %zu" state: 0 call: 0xc0055bf0 probe multi :
0x00000000
marker: net_socket_create format: "sock %p family %d type %d protocol %d fd %d" state: 0 call: 0xc0055bf0 probe multi : 0x00
000000
marker: net_socket_call format: "call %d a0 %lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: net_dev_receive format: "skb %p protocol #2u%hu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: net_dev_xmit format: "skb %p protocol #2u%hu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: net_insert_ifa_ipv4 format: "label %s address #4u%lu" state: 0 call: 0xc0055bf0 probe multi : 0x00000000
marker: net_del_ifa_ipv4 format: "label %s" state: 0 call: 0xc0055bf0 probe multi : 0x00000000

Thanks.

_________________________________________________________________
R?inventez comment vous restez en contact avec le nouveau Windows Live Messenger.
http://go.microsoft.com/?linkid=9650737
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/ltt-dev/attachments/20090309/d365dc49/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: config_9Mars2009
Type: application/octet-stream
Size: 22478 bytes
Desc: not available
URL: <http://lists.casi.polymtl.ca/pipermail/ltt-dev/attachments/20090309/d365dc49/attachment-0001.obj>

^ permalink raw reply	[flat|nested] 8+ messages in thread