I've been partying and working on an OSTRA rebirth, this time based on my current work on DWARF tools, so to give just a heads up, here is the current stage, explanations below: 1. build the kernel as usual + select CONFIG_DEBUG_INFO to insert debugging information, the resulting kernel will be larger but otherwise the same, the debug information, just like with any other project built with 'gcc -g' will be in separate ELF sections. 2. Run ctracer, the tool I'm writing, available at http://www.kernel.org/git/?p=linux/kernel/git/acme/pahole.git;a=summary ctracer --recursive -dir net/dccp/ --glob "*.ko" --kprobes vmlinux sock > ctracer.c '--recursive --dir net/dccp/' --glob "*.ko"' will tell ctracer to consider just the files in the net/dccp/ subtree '--kprobes vmlinux' its just for ctracer to find the needed structs and function prototypes for the kprobes routines and for the current trace relay agent, a lame one that just uses plain printk, but will be replaced by something along the lines of what is used in blktrace, or just the same, perhaps, haven't checked yet. finally 'sock' tells ctracer that we're interested only in functions that receives as one of its parameter a pointer to struct sock. The resulting ctracer.c file is available at: http://oops.ghostprotocols.net:81/acme/sock_ctracer.c Then, using the instructions in Documentation/kprobes.txt, we build the resulting kernel module, ctracer.c, for reference the makefile is very simple: ----------------- 8< ------------------ [acme@newtoy ctracer_example]$ cat Makefile obj-m := ctracer.o KDIR := /pub/scm/linux/kernel/git/acme/linux-2.6/ PWD := $(shell pwd) default: $(MAKE) -C $(KDIR) SUBDIRS=$(PWD) modules [acme@newtoy ctracer_example]$ ----------------- 8< ------------------ Then we load the DCCP modules: [root@qemu ~]# modprobe dccp_ccid3 [ 86.873785] CCID: Registered CCID 3 (ccid3) [root@qemu ~]# modprobe dccp_ipv4 And then the ctracer.ko module, that will complain about some symbols not being found, i.e. I haven't loaded ccid2.ko, dccp_ipv6.ko nor the dccpprobe.ko (that I hope to turn moot after I finish this work): [root@qemu ~]# insmod ./ctracer.ko [ 94.835016] register_jprobe(ccid2_hc_tx_packet_recv) failed, returned -22 [ 94.906545] register_kretprobe(ccid2_hc_tx_packet_recv) failed, returned -22 [ 94.991244] register_jprobe(ccid2_hc_tx_packet_sent) failed, returned -22 [ 95.072229] register_kretprobe(ccid2_hc_tx_packet_sent) failed, returned -22 [ 95.154525] register_jprobe(ccid2_hc_tx_send_packet) failed, returned -22 [ 95.236687] register_kretprobe(ccid2_hc_tx_send_packet) failed, returned -22 [ 95.315511] register_jprobe(ccid2_hc_tx_init) failed, returned -22 [ 95.389672] register_kretprobe(ccid2_hc_tx_init) failed, returned -22 [ 95.473402] register_jprobe(ccid2_hc_tx_exit) failed, returned -22 [ 95.559145] register_kretprobe(ccid2_hc_tx_exit) failed, returned -22 [ 95.642080] register_jprobe(ccid2_hc_rx_packet_recv) failed, returned -22 [ 95.725702] register_kretprobe(ccid2_hc_rx_packet_recv) failed, returned -22 [ 95.820803] register_jprobe(ccid2_hc_tx_dec_pipe) failed, returned -22 [ 95.903664] register_kretprobe(ccid2_hc_tx_dec_pipe) failed, returned -22 [ 95.986252] register_jprobe(ccid2_hc_tx_kill_rto_timer) failed, returned -22 [ 96.071975] register_kretprobe(ccid2_hc_tx_kill_rto_timer) failed, returned -22 [ 96.151152] register_jprobe(ccid2_start_rto_timer) failed, returned -22 [ 96.243973] register_kretprobe(ccid2_start_rto_timer) failed, returned -22 [ 96.327091] register_jprobe(ccid2_change_l_ack_ratio) failed, returned -22 [ 96.413197] register_kretprobe(ccid2_change_l_ack_ratio) failed, returned -22 This soft lockup is harmless so far, something related to qemu + kprobes, still have to investigate, but has not prevented me from testing what I have so far: [ 106.611513] BUG: soft lockup detected on CPU#0! [ 106.625659] [<c01150d8>] update_process_times+0x28/0x70 [ 106.641645] [<c010508b>] timer_interrupt+0x2b/0x50 [ 106.648264] [<c0128205>] handle_IRQ_event+0x25/0x50 [ 106.655091] [<c0129550>] handle_level_irq+0x0/0xc0 [ 106.668005] [<c01295a5>] handle_level_irq+0x55/0xc0 [ 106.716414] [<c0104023>] do_IRQ+0x63/0xb0 [ 106.720906] [<c0102a4f>] common_interrupt+0x23/0x28 [ 106.726948] [<c0127729>] kallsyms_expand_symbol+0x79/0xb0 [ 106.738641] [<c0127ded>] kallsyms_lookup_name+0x3d/0x80 [ 106.753817] [<c0260610>] longjmp_break_handler+0x0/0x130 [ 106.771530] [<d0806041>] jprobe_init+0x41/0xaf [ctracer] [ 106.777810] [<c0261245>] __register_kprobe+0x45/0x270 [ 106.828679] [<d0806041>] jprobe_init+0x41/0xaf [ctracer] [ 106.841134] [<c01258e5>] sys_init_module+0x155/0x1740 [ 106.849205] [<c01028d8>] syscall_call+0x7/0xb [ 106.859973] ======================= [ 115.678750] register_jprobe(dccp_diag_get_info) failed, returned -22 [ 115.846025] register_kretprobe(dccp_diag_get_info) failed, returned -22 [ 118.297134] register_jprobe(dccp_v6_conn_request) failed, returned -22 [ 118.452448] register_kretprobe(dccp_v6_conn_request) failed, returned -22 [ 118.593451] register_jprobe(dccp_v6_request_recv_sock) failed, returned -22 [ 118.743396] register_kretprobe(dccp_v6_request_recv_sock) failed, returned -22 [ 118.892009] register_jprobe(dccp_v6_send_check) failed, returned -22 [ 119.057726] register_kretprobe(dccp_v6_send_check) failed, returned -22 [ 119.231268] register_jprobe(dccp_v6_do_rcv) failed, returned -22 [ 119.400589] register_kretprobe(dccp_v6_do_rcv) failed, returned -22 [ 119.560109] register_jprobe(dccp_v6_connect) failed, returned -22 [ 119.745185] register_kretprobe(dccp_v6_connect) failed, returned -22 [ 119.944263] register_jprobe(dccp_v6_hash) failed, returned -22 [ 120.126660] register_kretprobe(dccp_v6_hash) failed, returned -22 [ 120.295032] register_jprobe(dccp_v6_init_sock) failed, returned -22 [ 120.463380] register_kretprobe(dccp_v6_init_sock) failed, returned -22 [ 120.633082] register_jprobe(dccp_v6_destroy_sock) failed, returned -22 [ 120.803029] register_kretprobe(dccp_v6_destroy_sock) failed, returned -22 [ 120.962845] register_jprobe(dccp_v6_get_port) failed, returned -22 [ 121.135645] register_kretprobe(dccp_v6_get_port) failed, returned -22 [ 121.335622] register_jprobe(dccp_v6_send_response) failed, returned -22 [ 121.531446] register_kretprobe(dccp_v6_send_response) failed, returned -22 [ 121.691987] register_jprobe(dccp_v6_ctl_send_reset) failed, returned -22 [ 121.871578] register_kretprobe(dccp_v6_ctl_send_reset) failed, returned -22 [ 122.047721] register_jprobe(jdccp_sendmsg) failed, returned -22 [ 122.210602] register_kretprobe(jdccp_sendmsg) failed, returned -22 OK, so we got 86 probes inserted: [ 122.226522] ctracer: registered 86 entry probes [ 122.244371] ctracer: registered 86 exit probes Now lets use ttcp for a quick test: [root@qemu ~]# ttcp -cacme -l256 -r & [1] 478 [root@qemu ~]# ttcp-r: buflen=256, nbuf=2048, align=16384/+0, port=5001 dccp(inet) [ 127.666592] -> dccp_v4_init_sock: sk=cf54c040 [ 127.668269] -> dccp_init_sock: sk=cf54c040 [ 127.669180] -> ccid_hc_rx_new: sk=cf54c040 [ 127.669478] -> ccid_new: sk=cf54c040 [ 128.072205] CCID: Registered CCID 2 (ccid2) [ 128.081212] <- ccid_new [ 128.081867] <- ccid_hc_rx_new [ 128.082171] -> ccid_hc_tx_new: sk=cf54c040 [ 128.082508] -> ccid_new: sk=cf54c040 [ 128.083224] <- ccid_new [ 128.083399] <- ccid_hc_tx_new [ 128.083632] -> dccp_init_xmit_timers: sk=cf54c040 [ 128.083972] <- dccp_init_xmit_timers [ 128.084219] <- dccp_init_sock [ 128.084580] <- dccp_v4_init_sock ttcp-r: socket [ 128.086479] -> dccp_v4_get_port: sk=cf54c040 [ 128.087111] <- dccp_v4_get_port [ 128.087842] -> dccp_setsockopt: sk=cf54c040 [ 128.088216] do_dccp_setsockopt: sockopt(PACKET_SIZE) is deprecated: fix your app [ 128.088665] <- dccp_setsockopt [ 128.088927] -> dccp_setsockopt: sk=cf54c040 [ 128.096660] <- dccp_setsockopt [ 128.098301] -> dccp_v4_get_port: sk=cf54c040 [ 128.098794] <- dccp_v4_get_port [ 128.099040] -> dccp_hash: sk=cf54c040 [ 128.099359] <- dccp_hash Above are the functions involved in listening to DCCP incoming connections. Now to run the client, sending only 5 256 byte sized packets (beware, I'm testing over loopback, so listening server, server and client sockets will be mixed, that is why the sk is printed): [root@qemu ~]# ttcp -cacme -l256 -n5 -t localhost [root@qemu ~]# ttcp-t: buflen=256, nbuf=5, align=16384/+0, port=5001 dccp(inet) -> localhost [ 133.284937] -> dccp_v4_init_sock: sk=cf54c3a0 [ 133.286262] -> dccp_init_sock: sk=cf54c3a0 [ 133.286642] -> ccid_hc_rx_new: sk=cf54c3a0 [ 133.287044] -> ccid_new: sk=cf54c3a0 [ 133.287300] <- ccid_new [ 133.287475] <- ccid_hc_rx_new [ 133.287683] -> ccid_hc_tx_new: sk=cf54c3a0 [ 133.287956] -> ccid_new: sk=cf54c3a0 [ 133.288509] <- ccid_new [ 133.288677] <- ccid_hc_tx_new [ 133.288888] -> dccp_init_xmit_timers: sk=cf54c3a0 [ 133.289190] <- dccp_init_xmit_timers [ 133.289414] <- dccp_init_sock [ 133.289604] <- dccp_v4_init_sock ttcp-t: socket [ 133.290673] -> dccp_setsockopt: sk=cf54c3a0 [ 133.290994] do_dccp_setsockopt: sockopt(PACKET_SIZE) is deprecated: fix your app [ 133.291432] <- dccp_setsockopt [ 133.296426] -> dccp_setsockopt: sk=cf54c3a0 [ 133.296739] <- dccp_setsockopt [ 133.297325] -> dccp_v4_connect: sk=cf54c3a0 [ 133.298607] -> dccp_set_state: sk=cf54c3a0 [ 133.298920] <- dccp_set_state [ 133.302385] -> dccp_connect: sk=cf54c3a0 [ 133.302733] -> dccp_sync_mss: sk=cf54c3a0 [ 133.303017] <- dccp_sync_mss [ 133.303362] -> dccp_skb_entail: sk=cf54c3a0 [ 133.303657] <- dccp_skb_entail [ 133.303995] -> dccp_transmit_skb: sk=cf54c3a0 [ 133.304424] -> dccp_insert_options: sk=cf54c3a0 [ 133.304952] <- dccp_insert_options [ 133.305285] -> dccp_v4_send_check: sk=cf54c3a0 [ 133.305777] <- dccp_v4_send_check [ 133.306571] -> dccp_write_space: sk=cf54c3a0 [ 133.306885] <- dccp_write_space [ 133.312335] -> dccp_v4_do_rcv: sk=cf54c040 [ 133.312783] -> dccp_rcv_state_process: sk=cf54c040 [ 133.313134] -> dccp_v4_conn_request: sk=cf54c040 [ 133.313658] -> dccp_parse_options: sk=cf54c040 [ 133.314100] -> dccp_feat_change_recv: sk=cf54c040 [ 133.314491] -> dccp_feat_update: sk=cf54c040 [ 133.314803] <- dccp_feat_update [ 133.315049] <- dccp_feat_change_recv [ 133.318120] -> dccp_feat_change_recv: sk=cf54c040 [ 133.318595] -> dccp_feat_update: sk=cf54c040 [ 133.318885] <- dccp_feat_update [ 133.319113] <- dccp_feat_change_recv [ 133.319352] -> dccp_feat_change_recv: sk=cf54c040 [ 133.319678] -> dccp_feat_update: sk=cf54c040 [ 133.320012] <- dccp_feat_update [ 133.320214] <- dccp_feat_change_recv [ 133.320456] <- dccp_parse_options [ 133.320772] -> dccp_v4_send_response: sk=cf54c040 [ 133.321197] -> dccp_make_response: sk=cf54c040 [ 133.324408] -> dccp_insert_options: sk=cf54c040 [ 133.324945] <- dccp_insert_options [ 133.325289] <- dccp_make_response [ 133.325708] -> dccp_write_space: sk=cf54c040 [ 133.326039] <- dccp_write_space [ 133.326559] <- dccp_v4_send_response [ 133.326882] <- dccp_v4_conn_request [ 133.327164] <- dccp_rcv_state_process [ 133.327409] <- dccp_v4_do_rcv [ 133.327887] <- dccp_transmit_skb [ 133.328140] <- dccp_connect [ 133.328600] <- dccp_v4_connect [ 133.328891] -> dccp_v4_do_rcv: sk=cf54c3a0 [ 133.329466] -> dccp_rcv_state_process: sk=cf54c3a0 [ 133.329838] -> dccp_write_space: sk=cf54c3a0 [ 133.330110] <- dccp_write_space [ 133.330383] -> dccp_parse_options: sk=cf54c3a0 [ 133.330690] -> dccp_feat_change_recv: sk=cf54c3a0 [ 133.332436] -> dccp_feat_update: sk=cf54c3a0 [ 133.332711] <- dccp_feat_update [ 133.332914] <- dccp_feat_change_recv [ 133.333180] -> dccp_feat_confirm_recv: sk=cf54c3a0 [ 133.333570] -> dccp_feat_update: sk=cf54c3a0 [ 133.333837] <- dccp_feat_update [ 133.334485] <- dccp_feat_confirm_recv [ 133.334739] -> dccp_feat_confirm_recv: sk=cf54c3a0 [ 133.335069] -> dccp_feat_update: sk=cf54c3a0 [ 133.335336] <- dccp_feat_update [ 133.335535] <- dccp_feat_confirm_recv [ 133.335873] -> dccp_feat_confirm_recv: sk=cf54c3a0 [ 133.336179] -> dccp_feat_update: sk=cf54c3a0 [ 133.336442] <- dccp_feat_update [ 133.336639] <- dccp_feat_confirm_recv [ 133.336866] <- dccp_parse_options [ 133.337304] -> dccp_sync_mss: sk=cf54c3a0 [ 133.337563] <- dccp_sync_mss [ 133.337767] -> dccp_set_state: sk=cf54c3a0 [ 133.338028] <- dccp_set_state [ 133.338318] -> dccp_send_ack: sk=cf54c3a0 [ 133.338638] -> dccp_transmit_skb: sk=cf54c3a0 [ 133.374588] -> dccp_insert_options: sk=cf54c3a0 [ 133.374971] -> dccp_insert_option_ackvec: sk=cf54c3a0 [ 133.375396] -> dccp_insert_option_elapsed_time: sk=cf54c3a0 [ 133.375791] <- dccp_insert_option_elapsed_time [ 133.376248] <- dccp_insert_option_ackvec [ 133.376580] <- dccp_insert_options [ 133.376836] -> dccp_v4_send_check: sk=cf54c3a0 [ 133.377127] <- dccp_v4_send_check [ 133.377391] -> dccp_write_space: sk=cf54c3a0 [ 133.377659] <- dccp_write_space [ 133.377870] <- dccp_transmit_skb [ 133.378120] <- dccp_send_ack [ 133.378440] <- dccp_rcv_state_process [ 133.378658] <- dccp_v4_do_rcv [ 133.378976] -> dccp_v4_do_rcv: sk=cf54c040 [ 133.379286] -> dccp_check_req: sk=cf54c040 [ 133.379602] -> dccp_v4_request_recv_sock: sk=cf54c040 [ 133.380017] -> dccp_create_openreq_child: sk=cf54c040 [ 133.380526] -> dccp_feat_clone: oldsk=cf54c040 [ 133.380788] -> dccp_feat_clone: newsk=cf54d7e0 [ 133.381135] <- dccp_feat_clone [ 133.381431] -> ccid_hc_rx_new: sk=cf54d7e0 [ 133.381685] -> ccid_new: sk=cf54d7e0 [ 133.381905] <- ccid_new [ 133.382056] <- ccid_hc_rx_new [ 133.382254] -> ccid_hc_tx_new: sk=cf54d7e0 [ 133.382506] -> ccid_new: sk=cf54d7e0 [ 133.382912] <- ccid_new [ 133.383069] <- ccid_hc_tx_new [ 133.383367] -> dccp_init_xmit_timers: sk=cf54d7e0 [ 133.383644] <- dccp_init_xmit_timers [ 133.383866] <- dccp_create_openreq_child [ 133.384160] -> dccp_sync_mss: sk=cf54d7e0 [ 133.384475] <- dccp_sync_mss [ 133.384701] <- dccp_v4_request_recv_sock [ 133.385012] <- dccp_check_req [ 133.385228] -> dccp_child_process: parent=cf54c040 [ 133.385503] -> dccp_child_process: child=cf54d7e0 [ 133.385817] -> dccp_rcv_state_process: sk=cf54d7e0 [ 133.386424] -> dccp_check_seqno: sk=cf54d7e0 [ 133.386839] <- dccp_check_seqno [ 133.387055] -> dccp_parse_options: sk=cf54d7e0 [ 133.387351] -> dccp_feat_confirm_recv: sk=cf54d7e0 [ 133.387797] -> dccp_feat_update: sk=cf54d7e0 [ 133.388052] <- dccp_feat_update [ 133.388251] <- dccp_feat_confirm_recv [ 133.388504] -> dccp_ackvec_parse: sk=cf54d7e0 [ 133.388805] <- dccp_ackvec_parse [ 133.389043] <- dccp_parse_options [ 133.402158] -> dccp_event_ack_recv: sk=cf54d7e0 [ 133.402524] -> dccp_ackvec_check_rcv_ackno: sk=cf54d7e0 [ 133.402873] <- dccp_ackvec_check_rcv_ackno [ 133.403121] <- dccp_event_ack_recv [ 133.403515] -> dccp_set_state: sk=cf54d7e0 [ 133.403777] <- dccp_set_state [ 133.403996] <- dccp_rcv_state_process [ 133.404264] <- dccp_child_process [ 133.404471] <- dccp_v4_do_rcv ttcp-r: accept from localhost.ghostprotocols.net [ 133.440047] -> dccp_recvmsg: sk=cf54d7e0 ttcp-t: connect [ 133.445579] -> dccp_sendmsg: sk=cf54c3a0 [ 133.446623] -> dccp_write_xmit: sk=cf54c3a0 [ 133.447057] -> dccp_transmit_skb: sk=cf54c3a0 [ 133.447405] -> dccp_insert_options: sk=cf54c3a0 [ 133.447758] -> dccp_insert_option_ackvec: sk=cf54c3a0 [ 133.448105] -> dccp_insert_option_elapsed_time: sk=cf54c3a0 [ 133.448470] <- dccp_insert_option_elapsed_time [ 133.448788] <- dccp_insert_option_ackvec [ 133.449075] <- dccp_insert_options [ 133.449322] -> dccp_v4_send_check: sk=cf54c3a0 [ 133.449653] <- dccp_v4_send_check [ 133.449954] -> dccp_write_space: sk=cf54c3a0 [ 133.450226] <- dccp_write_space [ 133.450698] -> dccp_v4_do_rcv: sk=cf54d7e0 [ 133.450991] -> dccp_rcv_established: sk=cf54d7e0 [ 133.451314] -> dccp_check_seqno: sk=cf54d7e0 [ 133.451607] <- dccp_check_seqno [ 133.451829] -> dccp_parse_options: sk=cf54d7e0 [ 133.454134] -> dccp_ackvec_parse: sk=cf54d7e0 [ 133.454421] <- dccp_ackvec_parse [ 133.454677] <- dccp_parse_options [ 133.454918] -> dccp_event_ack_recv: sk=cf54d7e0 [ 133.455282] -> dccp_ackvec_check_rcv_ackno: sk=cf54d7e0 [ 133.455605] <- dccp_ackvec_check_rcv_ackno [ 133.455857] <- dccp_event_ack_recv [ 133.456183] -> dccp_send_ack: sk=cf54d7e0 [ 133.456474] -> dccp_transmit_skb: sk=cf54d7e0 [ 133.456805] -> dccp_insert_options: sk=cf54d7e0 [ 133.457103] -> dccp_insert_option_ackvec: sk=cf54d7e0 [ 133.457432] -> dccp_insert_option_elapsed_time: sk=cf54d7e0 [ 133.457772] <- dccp_insert_option_elapsed_time [ 133.458049] <- dccp_insert_option_ackvec [ 133.458304] <- dccp_insert_options [ 133.483785] -> dccp_v4_send_check: sk=cf54d7e0 [ 133.484096] <- dccp_v4_send_check [ 133.484487] <- dccp_send_ack [ 133.484706] -> __dccp_rcv_established: sk=cf54d7e0 [ 133.485151] <- __dccp_rcv_established [ 133.485375] <- dccp_rcv_established [ 133.485591] <- dccp_v4_do_rcv [ 133.485914] <- dccp_transmit_skb [ 133.486220] <- dccp_write_xmit [ 133.486435] -> dccp_v4_do_rcv: sk=cf54c3a0 [ 133.486890] -> dccp_rcv_state_process: sk=cf54c3a0 [ 133.487184] -> dccp_check_seqno: sk=cf54c3a0 [ 133.487444] <- dccp_check_seqno [ 133.487648] -> dccp_parse_options: sk=cf54c3a0 [ 133.487928] -> dccp_ackvec_parse: sk=cf54c3a0 [ 133.488360] <- dccp_ackvec_parse [ 133.488559] <- dccp_parse_options [ 133.488775] -> dccp_event_ack_recv: sk=cf54c3a0 [ 133.489051] -> dccp_ackvec_check_rcv_ackno: sk=cf54c3a0 [ 133.489352] <- dccp_ackvec_check_rcv_ackno [ 133.489587] <- dccp_event_ack_recv [ 133.490279] -> dccp_set_state: sk=cf54c3a0 [ 133.490531] <- dccp_set_state [ 133.490768] <- dccp_rcv_state_process [ 133.490984] <- dccp_v4_do_rcv [ 133.491186] <- dccp_sendmsg [ 133.491874] <- dccp_recvmsg [ 133.492466] -> dccp_recvmsg: sk=cf54d7e0 [ 133.493110] -> dccp_sendmsg: sk=cf54c3a0 [ 133.493570] -> dccp_write_xmit: sk=cf54c3a0 [ 133.493884] -> dccp_transmit_skb: sk=cf54c3a0 [ 133.494165] -> dccp_insert_options: sk=cf54c3a0 [ 133.494452] -> dccp_insert_option_ackvec: sk=cf54c3a0 [ 133.494873] -> dccp_insert_option_elapsed_time: sk=cf54c3a0 [ 133.495206] <- dccp_insert_option_elapsed_time [ 133.495490] <- dccp_insert_option_ackvec [ 133.495731] <- dccp_insert_options [ 133.495961] -> dccp_v4_send_check: sk=cf54c3a0 [ 133.504076] <- dccp_v4_send_check [ 133.504433] -> dccp_write_space: sk=cf54c3a0 [ 133.504707] <- dccp_write_space [ 133.505091] -> dccp_v4_do_rcv: sk=cf54d7e0 [ 133.505368] -> dccp_rcv_established: sk=cf54d7e0 [ 133.505722] -> dccp_check_seqno: sk=cf54d7e0 [ 133.506013] <- dccp_check_seqno [ 133.506228] -> dccp_parse_options: sk=cf54d7e0 [ 133.506540] -> dccp_ackvec_parse: sk=cf54d7e0 [ 133.506844] <- dccp_ackvec_parse [ 133.507062] <- dccp_parse_options [ 133.507345] -> dccp_event_ack_recv: sk=cf54d7e0 [ 133.507642] -> dccp_ackvec_check_rcv_ackno: sk=cf54d7e0 [ 133.507962] <- dccp_ackvec_check_rcv_ackno [ 133.508213] <- dccp_event_ack_recv [ 133.508469] -> dccp_send_ack: sk=cf54d7e0 [ 133.508899] -> dccp_transmit_skb: sk=cf54d7e0 [ 133.509194] -> dccp_insert_options: sk=cf54d7e0 [ 133.509499] -> dccp_insert_option_ackvec: sk=cf54d7e0 [ 133.509830] -> dccp_insert_option_elapsed_time: sk=cf54d7e0 [ 133.510172] <- dccp_insert_option_elapsed_time [ 133.510576] <- dccp_insert_option_ackvec [ 133.510833] <- dccp_insert_options [ 133.511068] -> dccp_v4_send_check: sk=cf54d7e0 [ 133.511350] <- dccp_v4_send_check [ 133.511649] <- dccp_send_ack [ 133.512131] -> __dccp_rcv_established: sk=cf54d7e0 [ 133.512449] <- __dccp_rcv_established [ 133.512677] <- dccp_rcv_established [ 133.512895] <- dccp_v4_do_rcv [ 133.513147] <- dccp_transmit_skb [ 133.513392] <- dccp_write_xmit [ 133.513667] -> dccp_v4_do_rcv: sk=cf54c3a0 [ 133.513936] -> dccp_rcv_established: sk=cf54c3a0 [ 133.514230] -> dccp_check_seqno: sk=cf54c3a0 [ 133.514501] <- dccp_check_seqno [ 133.514713] -> dccp_parse_options: sk=cf54c3a0 [ 133.517807] -> dccp_ackvec_parse: sk=cf54c3a0 [ 133.518109] <- dccp_ackvec_parse [ 133.518361] <- dccp_parse_options [ 133.518588] -> dccp_event_ack_recv: sk=cf54c3a0 [ 133.518880] -> dccp_ackvec_check_rcv_ackno: sk=cf54c3a0 [ 133.519209] <- dccp_ackvec_check_rcv_ackno [ 133.519459] <- dccp_event_ack_recv [ 133.527414] -> __dccp_rcv_established: sk=cf54c3a0 [ 133.529040] <- __dccp_rcv_established [ 133.529324] <- dccp_rcv_established [ 133.529546] <- dccp_v4_do_rcv [ 133.529768] <- dccp_sendmsg [ 133.530262] <- dccp_recvmsg [ 133.531818] -> dccp_recvmsg: sk=cf54d7e0 [ 133.532459] -> dccp_sendmsg: sk=cf54c3a0 [ 133.532933] -> dccp_write_xmit: sk=cf54c3a0 [ 133.533245] -> dccp_transmit_skb: sk=cf54c3a0 [ 133.533541] -> dccp_insert_options: sk=cf54c3a0 [ 133.533849] -> dccp_insert_option_ackvec: sk=cf54c3a0 [ 133.534254] -> dccp_insert_option_elapsed_time: sk=cf54c3a0 [ 133.534607] <- dccp_insert_option_elapsed_time [ 133.534908] <- dccp_insert_option_ackvec [ 133.535165] <- dccp_insert_options [ 133.535410] -> dccp_v4_send_check: sk=cf54c3a0 [ 133.538449] <- dccp_v4_send_check [ 133.538850] -> dccp_write_space: sk=cf54c3a0 [ 133.539126] <- dccp_write_space [ 133.539501] -> dccp_v4_do_rcv: sk=cf54d7e0 [ 133.539778] -> dccp_rcv_established: sk=cf54d7e0 [ 133.540077] -> dccp_check_seqno: sk=cf54d7e0 [ 133.540505] <- dccp_check_seqno [ 133.540722] -> dccp_parse_options: sk=cf54d7e0 [ 133.541035] -> dccp_ackvec_parse: sk=cf54d7e0 [ 133.541337] <- dccp_ackvec_parse [ 133.541554] <- dccp_parse_options [ 133.542999] -> dccp_event_ack_recv: sk=cf54d7e0 [ 133.543300] -> dccp_ackvec_check_rcv_ackno: sk=cf54d7e0 [ 133.550094] <- dccp_ackvec_check_rcv_ackno [ 133.550359] <- dccp_event_ack_recv [ 133.550627] -> dccp_send_ack: sk=cf54d7e0 [ 133.550914] -> dccp_transmit_skb: sk=cf54d7e0 [ 133.553507] -> dccp_insert_options: sk=cf54d7e0 [ 133.553817] -> dccp_insert_option_ackvec: sk=cf54d7e0 [ 133.554148] -> dccp_insert_option_elapsed_time: sk=cf54d7e0 [ 133.554587] <- dccp_insert_option_elapsed_time [ 133.554870] <- dccp_insert_option_ackvec [ 133.555128] <- dccp_insert_options [ 133.555363] -> dccp_v4_send_check: sk=cf54d7e0 [ 133.555653] <- dccp_v4_send_check [ 133.556297] <- dccp_send_ack [ 133.556507] -> __dccp_rcv_established: sk=cf54d7e0 [ 133.556815] <- __dccp_rcv_established [ 133.557043] <- dccp_rcv_established [ 133.557261] <- dccp_v4_do_rcv [ 133.557582] <- dccp_transmit_skb [ 133.557831] <- dccp_write_xmit [ 133.558047] -> dccp_v4_do_rcv: sk=cf54c3a0 [ 133.558317] -> dccp_rcv_established: sk=cf54c3a0 [ 133.558615] -> dccp_check_seqno: sk=cf54c3a0 [ 133.558890] <- dccp_check_seqno [ 133.559137] -> dccp_parse_options: sk=cf54c3a0 [ 133.559432] -> dccp_ackvec_parse: sk=cf54c3a0 [ 133.559716] <- dccp_ackvec_parse [ 133.559932] <- dccp_parse_options [ 133.560157] -> dccp_event_ack_recv: sk=cf54c3a0 [ 133.560449] -> dccp_ackvec_check_rcv_ackno: sk=cf54c3a0 [ 133.560822] <- dccp_ackvec_check_rcv_ackno [ 133.561072] <- dccp_event_ack_recv [ 133.561394] -> __dccp_rcv_established: sk=cf54c3a0 [ 133.561721] <- __dccp_rcv_established [ 133.561946] <- dccp_rcv_established [ 133.562162] <- dccp_v4_do_rcv [ 133.564681] <- dccp_sendmsg [ 133.565166] <- dccp_recvmsg [ 133.566173] -> dccp_recvmsg: sk=cf54d7e0 [ 133.566739] -> dccp_sendmsg: sk=cf54c3a0 [ 133.567248] -> dccp_write_xmit: sk=cf54c3a0 [ 133.567558] -> dccp_transmit_skb: sk=cf54c3a0 [ 133.567852] -> dccp_insert_options: sk=cf54c3a0 [ 133.568158] -> dccp_insert_option_ackvec: sk=cf54c3a0 [ 133.591368] -> dccp_insert_option_elapsed_time: sk=cf54c3a0 [ 133.592838] <- dccp_insert_option_elapsed_time [ 133.593144] <- dccp_insert_option_ackvec [ 133.593389] <- dccp_insert_options [ 133.593628] -> dccp_v4_send_check: sk=cf54c3a0 [ 133.594116] <- dccp_v4_send_check [ 133.594413] -> dccp_write_space: sk=cf54c3a0 [ 133.594671] <- dccp_write_space [ 133.595047] -> dccp_v4_do_rcv: sk=cf54d7e0 [ 133.595400] -> dccp_rcv_established: sk=cf54d7e0 [ 133.595684] -> dccp_check_seqno: sk=cf54d7e0 [ 133.595956] <- dccp_check_seqno [ 133.596160] -> dccp_parse_options: sk=cf54d7e0 [ 133.596456] -> dccp_ackvec_parse: sk=cf54d7e0 [ 133.596743] <- dccp_ackvec_parse [ 133.597018] <- dccp_parse_options [ 133.597233] -> dccp_event_ack_recv: sk=cf54d7e0 [ 133.597511] -> dccp_ackvec_check_rcv_ackno: sk=cf54d7e0 [ 133.597822] <- dccp_ackvec_check_rcv_ackno [ 133.598057] <- dccp_event_ack_recv [ 133.598299] -> dccp_send_ack: sk=cf54d7e0 [ 133.598604] -> dccp_transmit_skb: sk=cf54d7e0 [ 133.598879] -> dccp_insert_options: sk=cf54d7e0 [ 133.599166] -> dccp_insert_option_ackvec: sk=cf54d7e0 [ 133.599476] -> dccp_insert_option_elapsed_time: sk=cf54d7e0 [ 133.599794] <- dccp_insert_option_elapsed_time [ 133.600108] <- dccp_insert_option_ackvec [ 133.600348] <- dccp_insert_options [ 133.600565] -> dccp_v4_send_check: sk=cf54d7e0 [ 133.600829] <- dccp_v4_send_check [ 133.601117] <- dccp_send_ack [ 133.601310] -> __dccp_rcv_established: sk=cf54d7e0 [ 133.601633] <- __dccp_rcv_established [ 133.601846] <- dccp_rcv_established [ 133.602051] <- dccp_v4_do_rcv [ 133.602279] <- dccp_transmit_skb [ 133.602512] <- dccp_write_xmit [ 133.602714] -> dccp_v4_do_rcv: sk=cf54c3a0 [ 133.602967] -> dccp_rcv_established: sk=cf54c3a0 [ 133.603382] -> dccp_check_seqno: sk=cf54c3a0 [ 133.603640] <- dccp_check_seqno [ 133.603841] -> dccp_parse_options: sk=cf54c3a0 [ 133.604115] -> dccp_ackvec_parse: sk=cf54c3a0 [ 133.604374] <- dccp_ackvec_parse [ 133.604573] <- dccp_parse_options [ 133.604840] -> dccp_event_ack_recv: sk=cf54c3a0 [ 133.605115] -> dccp_ackvec_check_rcv_ackno: sk=cf54c3a0 [ 133.605413] <- dccp_ackvec_check_rcv_ackno [ 133.605647] <- dccp_event_ack_recv [ 133.605960] -> __dccp_rcv_established: sk=cf54c3a0 [ 133.606298] <- __dccp_rcv_established [ 133.606511] <- dccp_rcv_established [ 133.606715] <- dccp_v4_do_rcv [ 133.606910] <- dccp_sendmsg [ 133.607360] <- dccp_recvmsg [ 133.615973] -> dccp_recvmsg: sk=cf54d7e0 [ 133.617060] -> dccp_sendmsg: sk=cf54c3a0 [ 133.617668] -> dccp_write_xmit: sk=cf54c3a0 [ 133.617981] -> dccp_transmit_skb: sk=cf54c3a0 [ 133.618278] -> dccp_insert_options: sk=cf54c3a0 [ 133.618586] -> dccp_insert_option_ackvec: sk=cf54c3a0 [ 133.619066] -> dccp_insert_option_elapsed_time: sk=cf54c3a0 [ 133.619426] <- dccp_insert_option_elapsed_time [ 133.619731] <- dccp_insert_option_ackvec [ 133.619987] <- dccp_insert_options [ 133.620233] -> dccp_v4_send_check: sk=cf54c3a0 [ 133.620568] <- dccp_v4_send_check [ 133.620867] -> dccp_write_space: sk=cf54c3a0 [ 133.621138] <- dccp_write_space [ 133.621522] -> dccp_v4_do_rcv: sk=cf54d7e0 [ 133.621797] -> dccp_rcv_established: sk=cf54d7e0 [ 133.622351] -> dccp_check_seqno: sk=cf54d7e0 [ 133.622645] <- dccp_check_seqno [ 133.622862] -> dccp_parse_options: sk=cf54d7e0 [ 133.623173] -> dccp_ackvec_parse: sk=cf54d7e0 [ 133.623474] <- dccp_ackvec_parse [ 133.623746] <- dccp_parse_options [ 133.623985] -> dccp_event_ack_recv: sk=cf54d7e0 [ 133.624279] -> dccp_ackvec_check_rcv_ackno: sk=cf54d7e0 [ 133.624599] <- dccp_ackvec_check_rcv_ackno [ 133.624850] <- dccp_event_ack_recv [ 133.625097] -> dccp_send_ack: sk=cf54d7e0 [ 133.628169] -> dccp_transmit_skb: sk=cf54d7e0 [ 133.628526] -> dccp_insert_options: sk=cf54d7e0 [ 133.628830] -> dccp_insert_option_ackvec: sk=cf54d7e0 [ 133.629161] -> dccp_insert_option_elapsed_time: sk=cf54d7e0 [ 133.629505] <- dccp_insert_option_elapsed_time [ 133.629782] <- dccp_insert_option_ackvec [ 133.630067] <- dccp_insert_options [ 133.630300] -> dccp_v4_send_check: sk=cf54d7e0 [ 133.630582] <- dccp_v4_send_check [ 133.630890] <- dccp_send_ack [ 133.631095] -> __dccp_rcv_established: sk=cf54d7e0 [ 133.631402] <- __dccp_rcv_established [ 133.631758] <- dccp_rcv_established [ 133.632129] <- dccp_v4_do_rcv [ 133.632419] <- dccp_transmit_skb [ 133.632663] <- dccp_write_xmit [ 133.632877] -> dccp_v4_do_rcv: sk=cf54c3a0 [ 133.644479] -> dccp_rcv_established: sk=cf54c3a0 [ 133.644798] -> dccp_check_seqno: sk=cf54c3a0 [ 133.645080] <- dccp_check_seqno [ 133.645298] -> dccp_parse_options: sk=cf54c3a0 [ 133.645594] -> dccp_ackvec_parse: sk=cf54c3a0 [ 133.645926] <- dccp_ackvec_parse [ 133.646144] <- dccp_parse_options [ 133.646368] -> dccp_event_ack_recv: sk=cf54c3a0 [ 133.646661] -> dccp_ackvec_check_rcv_ackno: sk=cf54c3a0 [ 133.646980] <- dccp_ackvec_check_rcv_ackno [ 133.647285] <- dccp_event_ack_recv [ 133.647626] -> __dccp_rcv_established: sk=cf54c3a0 [ 133.647957] <- __dccp_rcv_established [ 133.648182] <- dccp_rcv_established [ 133.648401] <- dccp_v4_do_rcv [ 133.648640] <- dccp_sendmsg [ 133.649161] <- dccp_recvmsg [ 133.649705] -> dccp_recvmsg: sk=cf54d7e0 ttcp-t: 1280 bytes in 0.19 real seconds = 6.42 KB/sec +++ ttcp-t: 5 I/O calls, msec/call = 39.87, calls/sec = 25.68 ttcp-t: 0.0user 0.1sys 0:00real 89% 0i+0d 0maxrss 0+1pf 0+5csw [ 133.690597] -> dccp_close: sk=cf54c3a0 [ 133.691906] -> dccp_set_state: sk=cf54c3a0 [ 133.692281] <- dccp_set_state [ 133.692565] -> dccp_send_close: sk=cf54c3a0 [ 133.693029] -> dccp_write_xmit: sk=cf54c3a0 [ 133.693309] <- dccp_write_xmit [ 133.693526] -> dccp_skb_entail: sk=cf54c3a0 [ 133.693797] <- dccp_skb_entail [ 133.694129] -> dccp_transmit_skb: sk=cf54c3a0 [ 133.694542] -> dccp_insert_options: sk=cf54c3a0 [ 133.694882] -> dccp_insert_option_ackvec: sk=cf54c3a0 [ 133.695333] -> dccp_insert_option_elapsed_time: sk=cf54c3a0 [ 133.695708] <- dccp_insert_option_elapsed_time [ 133.696108] <- dccp_insert_option_ackvec [ 133.696436] <- dccp_insert_options [ 133.696760] -> dccp_v4_send_check: sk=cf54c3a0 [ 133.697144] <- dccp_v4_send_check [ 133.698153] -> dccp_write_space: sk=cf54c3a0 [ 133.698444] <- dccp_write_space [ 133.699899] -> dccp_v4_do_rcv: sk=cf54d7e0 [ 133.700192] -> dccp_rcv_established: sk=cf54d7e0 [ 133.700497] -> dccp_check_seqno: sk=cf54d7e0 [ 133.706459] <- dccp_check_seqno [ 133.707497] -> dccp_parse_options: sk=cf54d7e0 [ 133.707940] -> dccp_ackvec_parse: sk=cf54d7e0 [ 133.708365] <- dccp_ackvec_parse [ 133.708697] <- dccp_parse_options [ 133.708952] -> dccp_event_ack_recv: sk=cf54d7e0 [ 133.709274] -> dccp_ackvec_check_rcv_ackno: sk=cf54d7e0 [ 133.709626] <- dccp_ackvec_check_rcv_ackno [ 133.709886] <- dccp_event_ack_recv [ 133.710259] -> __dccp_rcv_established: sk=cf54d7e0 [ 133.710599] -> dccp_rcv_close: sk=cf54d7e0 [ 133.710916] -> dccp_send_reset: sk=cf54d7e0 [ 133.711319] -> dccp_insert_options: sk=cf54d7e0 [ 133.711667] -> dccp_insert_option_ackvec: sk=cf54d7e0 [ 133.712031] -> dccp_insert_option_elapsed_time: sk=cf54d7e0 [ 133.712372] <- dccp_insert_option_elapsed_time [ 133.712651] <- dccp_insert_option_ackvec [ 133.712916] <- dccp_insert_options [ 133.713213] -> dccp_v4_send_check: sk=cf54d7e0 [ 133.713686] <- dccp_v4_send_check [ 133.714199] <- dccp_send_reset [ 133.714428] -> dccp_fin: sk=cf54d7e0 [ 133.714736] <- dccp_fin [ 133.716001] -> dccp_set_state: sk=cf54d7e0 [ 133.716307] -> dccp_unhash: sk=cf54d7e0 [ 133.716779] <- dccp_unhash [ 133.717010] <- dccp_set_state [ 133.717216] <- dccp_rcv_close [ 133.717421] <- __dccp_rcv_established [ 133.717658] <- dccp_rcv_established [ 133.717893] <- dccp_v4_do_rcv [ 133.718404] <- dccp_transmit_skb [ 133.718617] <- dccp_send_close [ 133.718877] -> dccp_v4_do_rcv: sk=cf54c3a0 [ 133.719168] -> dccp_rcv_state_process: sk=cf54c3a0 [ 133.719499] -> dccp_check_seqno: sk=cf54c3a0 [ 133.719819] <- dccp_check_seqno [ 133.720041] -> dccp_parse_options: sk=cf54c3a0 [ 133.720358] -> dccp_ackvec_parse: sk=cf54c3a0 [ 133.720642] <- dccp_ackvec_parse [ 133.720886] <- dccp_parse_options [ 133.721126] -> dccp_event_ack_recv: sk=cf54c3a0 [ 133.721454] -> dccp_ackvec_check_rcv_ackno: sk=cf54c3a0 [ 133.721774] <- dccp_ackvec_check_rcv_ackno [ 133.722024] <- dccp_event_ack_recv [ 133.722344] -> dccp_fin: sk=cf54c3a0 [ 133.722578] <- dccp_fin [ 133.732499] -> dccp_time_wait: sk=cf54c3a0 [ 133.734857] -> dccp_done: sk=cf54c3a0 [ 133.735125] -> dccp_set_state: sk=cf54c3a0 [ 133.735479] -> dccp_unhash: sk=cf54c3a0 [ 133.735720] <- dccp_unhash [ 133.735906] <- dccp_set_state [ 133.736201] -> dccp_destroy_sock: sk=cf54c3a0 [ 133.736538] -> dccp_write_space: sk=cf54c3a0 [ 133.736789] <- dccp_write_space [ 133.737236] -> ccid_hc_rx_delete: sk=cf54c3a0 [ 133.737549] -> ccid_delete: sk=cf54c3a0 [ 133.737839] <- ccid_delete [ 133.738016] <- ccid_hc_rx_delete [ 133.738237] -> ccid_hc_tx_delete: sk=cf54c3a0 [ 133.738565] -> ccid_delete: sk=cf54c3a0 [ 133.738871] <- ccid_delete [ 133.739042] <- ccid_hc_tx_delete [ 133.739300] <- dccp_destroy_sock [ 133.739596] <- dccp_done [ 133.739760] <- dccp_time_wait [ 133.739955] <- dccp_rcv_state_process [ 133.740219] <- dccp_v4_do_rcv [ 133.740577] <- dccp_close [ 133.742279] <- dccp_recvmsg ttcp-r: 1280 bytes in 0.28 real seconds = 4.53 KB/sec +++ ttcp-r: 6 I/O calls, msec/call = 47.07, calls/sec = 21.76 ttcp-r: 0.0user 0.0sys 0:00real 7% 0i+0d 0maxrss 0+1pf 6+0csw [ 133.759450] -> dccp_close: sk=cf54c040 [ 133.759880] -> dccp_set_state: sk=cf54c040 [ 133.760172] -> dccp_unhash: sk=cf54c040 [ 133.760470] <- dccp_unhash [ 133.761359] <- dccp_set_state [ 133.761685] -> dccp_destroy_sock: sk=cf54c040 [ 133.762020] -> ccid_hc_rx_delete: sk=cf54c040 [ 133.762383] -> ccid_delete: sk=cf54c040 [ 133.762637] <- ccid_delete [ 133.762815] <- ccid_hc_rx_delete [ 133.763034] -> ccid_hc_tx_delete: sk=cf54c040 [ 133.763321] -> ccid_delete: sk=cf54c040 [ 133.763576] <- ccid_delete [ 133.764814] <- ccid_hc_tx_delete [ 133.765377] <- dccp_destroy_sock [ 133.765698] <- dccp_close [ 133.766005] -> dccp_close: sk=cf54d7e0 [ 133.766276] -> dccp_destroy_sock: sk=cf54d7e0 [ 133.766600] -> ccid_hc_rx_delete: sk=cf54d7e0 [ 133.773472] -> ccid_delete: sk=cf54d7e0 [ 133.773731] <- ccid_delete [ 133.773901] <- ccid_hc_rx_delete [ 133.774112] -> ccid_hc_tx_delete: sk=cf54d7e0 [ 133.774378] -> ccid_delete: sk=cf54d7e0 [ 133.774616] <- ccid_delete [ 133.775097] <- ccid_hc_tx_delete [ 133.775299] <- dccp_destroy_sock [ 133.775715] <- dccp_close [1]- Done ttcp -cacme -l256 -r [2]+ Done ttcp -cacme -l256 -n5 -t localhost [root@qemu ~]# OSTRA had this problem of involving way too many steps and requiring rebuilding the kernel with a meta-compiler, now we can even just share the resulting tracer modules, not even requiring that people interested in just debugging use ctracer, just to build the "script", collect the trace data and post-process it. OK, next steps will be to have a better relay channel, get the information to userspace and use ostra-cg, mostly unmodified, to get what we had with OSTRA: http://oops.ghostprotocols.net:81/dccp/ostra/delay_100ms_loss20percent_packet_size_256/ Just that now we don't have to build a special kernel using ostra-grep + ostra-patch, production kernels will be OK to use this tool as long as it has kprobes enabled, and that is the rule nowadays for all distros I know of and also has a companion kernel-debug rpm package built with debug info, and that is, again, the rule with at least the major distros. Future work also involves studying generating dtrace or systemtap scripts, but for now I'm going the plain kprobes way. Ah, just pushed the latest batch, should take some time to hit www.kernel.org/git. And yes, I haven't forgot the DCCP patch backlog :-) - Arnaldo - To unsubscribe from this list: send the line "unsubscribe dccp" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
