06/04/16 -------- What is the type of args[3]? # dtrace -lvn 'tcp::tcp_send_data:send' ID PROVIDER MODULE FUNCTION NAME 7187 tcp ip tcp_send_data send Probe Description Attributes Identifier Names: Private Data Semantics: Private Dependency Class: Unknown Argument Attributes Identifier Names: Evolving Data Semantics: Evolving Dependency Class: ISA Argument Types args[0]: pktinfo_t * args[1]: csinfo_t * args[2]: ipinfo_t * args[3]: tcpsinfo_t * args[4]: tcpinfo_t * It's tcpsinfo_t. Okay, how is this produced? Look at the probe site in tcp_send_data(). DTRACE_TCP5(send, mblk_t *, NULL, ip_xmit_attr_t *, connp->conn_ixa, __dtrace_tcp_void_ip_t *, mp->b_rptr, tcp_t *, tcp, __dtrace_tcp_tcph_t *, &mp->b_rptr[connp->conn_ixa->ixa_ip_hdr_length]); The type is "tcp_t *". A translator is used to populate the tcpsinfo_t from the tcp_t. The definition of tcpsinfo_t and its translator are found in /usr/lib/dtrace/tcp.d. The structure: typedef struct tcpsinfo { uintptr_t tcps_addr; int tcps_local; /* is delivered locally, boolean */ int tcps_active; /* active open (from here), boolean */ uint16_t tcps_lport; /* local port */ uint16_t tcps_rport; /* remote port */ string tcps_laddr; /* local address, as a string */ string tcps_raddr; /* remote address, as a string */ int32_t tcps_state; /* TCP state */ uint32_t tcps_iss; /* Initial sequence # sent */ uint32_t tcps_suna; /* sequence # sent but unacked */ uint32_t tcps_snxt; /* next sequence # to send */ uint32_t tcps_rack; /* sequence # we have acked */ uint32_t tcps_rnxt; /* next sequence # expected */ uint32_t tcps_swnd; /* send window size */ int32_t tcps_snd_ws; /* send window scaling */ uint32_t tcps_rwnd; /* receive window size */ int32_t tcps_rcv_ws; /* receive window scaling */ uint32_t tcps_cwnd; /* congestion window */ uint32_t tcps_cwnd_ssthresh; /* threshold for congestion avoidance */ uint32_t tcps_sack_fack; /* SACK sequence # we have acked */ uint32_t tcps_sack_snxt; /* next SACK seq # for retransmission */ uint32_t tcps_rto; /* round-trip timeout, msec */ uint32_t tcps_mss; /* max segment size */ int tcps_retransmit; /* retransmit send event, boolean */ } tcpsinfo_t; The translator: #pragma D binding "1.6.3" translator translator tcpsinfo_t < tcp_t *T > { tcps_addr = (uintptr_t)T; /* * The following two members should just use tcp_t->tcp_loopback * and tcp_t->tcp_active_open, however these are bit fields and * can't be used until CR 6876830 is fixed. Meanwhile we source * them a different way. */ tcps_local = T ? T->tcp_ipha ? T->tcp_ipha->ipha_src == T->tcp_ipha->ipha_dst : 1 : 0; tcps_active = T ? !T->tcp_saved_listener : 0; tcps_lport = T ? ntohs(T->tcp_connp->u_port.connu_ports.connu_lport) : 0; tcps_rport = T ? ntohs(T->tcp_connp->u_port.connu_ports.connu_fport) : 0; tcps_laddr = T ? inet_ntoa6(&T->tcp_connp->connua_v6addr.connua_laddr) : ""; tcps_raddr = T ? inet_ntoa6(&T->tcp_connp->connua_v6addr.connua_faddr) : ""; tcps_state = T ? T->tcp_state : TCP_STATE_CLOSED; tcps_iss = T ? T->tcp_iss : 0; tcps_suna = T ? T->tcp_suna : 0; tcps_snxt = T ? T->tcp_snxt : 0; tcps_rack = T ? T->tcp_rack : 0; tcps_rnxt = T ? T->tcp_rnxt : 0; tcps_swnd = T ? T->tcp_swnd : 0; tcps_snd_ws = T ? T->tcp_snd_ws : 0; tcps_rwnd = T ? T->tcp_rwnd : 0; tcps_rcv_ws = T ? T->tcp_rcv_ws : 0; tcps_cwnd = T ? T->tcp_cwnd : 0; tcps_cwnd_ssthresh = T ? T->tcp_cwnd_ssthresh : 0; tcps_sack_fack = T ? T->tcp_sack_info.tcp_fack : 0; tcps_sack_snxt = T ? T->tcp_sack_info.tcp_sack_snxt : 0; tcps_rto = T ? T->tcp_rto : 0; tcps_mss = T ? T->tcp_mss : 0; /* * Determine if send is a retransmission by comparing the seq # to * tcp_rexmit_nxt/tcp_rexmit_max - if the value is >= rexmit_nxt and * < rexmit_max, this is a retransmission. Cannot use tcp_rexmit * bitfield value due to CR 6876830. */ tcps_retransmit = T && probename == "send" && arg4 != NULL && ntohl(*(uint32_t *)((tcph_t *)arg4)->th_seq) >= T->tcp_rexmit_nxt && ntohl(*(uint32_t *)((tcph_t *)arg4)->th_seq) < T->tcp_rexmit_max ? 1 : 0; }; Where does the "invalid alignment" message come from and why does DTrace produce it? $ csgrep.sh -e "invalid alignment" Searching for egrep pattern invalid alignment lib/libdtrace/common/dt_error.c:205: () { DTRACEFLT_BADALIGN, "invalid alignment" }, lib/libdtrace/common/dt_errtags.h:217: () D_PROC_ALIGN, /* byte offset has invalid alignment */ It appears DTRACEFLT_BADALIGN is what I'm looking for. I also traced D_PROC_ALIGN but it produces a different error message. Okay, so how is DTRACEFLT_BADALIGN used throughout the code? $ csgrep.sh DTRACEFLT_BADALIGN Searching for symbol DTRACEFLT_BADALIGN uts/common/sys/dtrace.h:1146: () #define DTRACEFLT_BADALIGN 2 cmd/mdb/common/modules/dtrace/dtrace.c:1464: (dtrace_helptrace) f == DTRACEFLT_BADALIGN ? "BADALIGN" : lib/libdtrace/common/dt_error.c:205: (dtrace_faultstr) { DTRACEFLT_BADALIGN, "invalid alignment" }, lib/libdtrace/common/dt_handle.c:206: (dt_handle_err) case DTRACEFLT_BADALIGN: lib/libdtrace_jni/common/dtj_consume.c:302: (dtj_errhandler) case DTRACEFLT_BADALIGN: lib/libdtrace_jni/common/dtj_error.c:50: (dtj_get_fault_name) case DTRACEFLT_BADALIGN: uts/common/dtrace/dtrace.c:458: (DTRACE_FLAGS2FLT) ((flags) & CPU_DTRACE_BADALIGN) ? DTRACEFLT_BADALIGN : \ Two things: 1. I hope there is no hard-coded use of 2. 2. DTRACEFLT_BADALIGN doesn't appear to be used directly but instead converted from uses of CPU_DTRACE_BADALIGN. $ csgrep.sh CPU_DTRACE_BADALIGN Searching for symbol CPU_DTRACE_BADALIGN uts/common/dtrace/dtrace.c:368: (DTRACE_ALIGNCHECK) *flags |= CPU_DTRACE_BADALIGN; \ uts/common/dtrace/dtrace.c:458: (DTRACE_FLAGS2FLT) ((flags) & CPU_DTRACE_BADALIGN) ? DTRACEFLT_BADALIGN : \ uts/common/dtrace/dtrace.c:6284: (dtrace_dif_emulate) *flags |= CPU_DTRACE_BADALIGN; uts/common/dtrace/dtrace.c:6298: (dtrace_dif_emulate) *flags |= CPU_DTRACE_BADALIGN; uts/common/dtrace/dtrace.c:6312: (dtrace_dif_emulate) *flags |= CPU_DTRACE_BADALIGN; uts/common/sys/cpuvar.h:362: (defined) #define CPU_DTRACE_BADALIGN 0x0008 uts/common/sys/cpuvar.h:375: (CPU_DTRACE_FAULT) #define CPU_DTRACE_FAULT (CPU_DTRACE_BADADDR | CPU_DTRACE_BADALIGN | \ uts/sparc/dtrace/fasttrap_isa.c:211: (fasttrap_anarg) CPU_DTRACE_BADALIGN); uts/sparc/dtrace/fasttrap_isa.c:218: (fasttrap_anarg) CPU_DTRACE_BADALIGN); I also need to check for all uses of DTRACE_ALIGNCHECK. Which is only used by DTRACE_LOADFUNC. $ csgrep.sh DTRACE_ALIGNCHECK Searching for symbol DTRACE_ALIGNCHECK uts/common/dtrace/dtrace.c:366: () #define DTRACE_ALIGNCHECK(addr, size, flags) \ uts/common/dtrace/dtrace.c:373: () #define DTRACE_ALIGNCHECK(addr, size, flags) uts/common/dtrace/dtrace.c:410: (DTRACE_LOADFUNC) DTRACE_ALIGNCHECK(addr, size, flags); \ And DTRACE_LOADFUNC is really 4 functions: dtrace_load{8,16,32,64}(). So, I need to study uses of: 1. CPU_DTRACE_BADALIGN 2. dtrace_load{8,16,32,64}() But before I get ahead of myself I need to make sure I fully understand what the error message is telling me. Obviously, it has to do with bad alignment. But what are the exact details? As hinted at by the cscope output for DTRACEFLT_BADALIGN the error message is created in dt_handler_err(). There error message for reference: dtrace: error on enabled probe ID 2 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff161c71127a) in action #1 at DIF offset 416 What I want to know is which parts aren't static text and what they mean. The more information I have the better chance I have of figuring this out. * "probe id 2" -- referred to as the epid in the code (enabled probde id). I'm not sure what enabled probe id is but I'll come back to this. * "(ID 7187" -- errpd->dtpd_id, the probe identifier. * "tcp:ip:tcp_send_data:send" -- the provider, module, function, and name of the probe. * "invalid alignment" -- dtrace_faultstr(dtp, err.dteda_fault). dtp arg isn't used. err.dteda_fault is obviously DTRACEFLT_BADALIGN. * (0xffffff161c71127a) -- details. For bad alignment this is the address in err.dteda_addr. This is the "address of the fault". I'm not sure if that means address of the probe or the address of the data it tried to read? Or maybe one of the members it tried to read? Thinking out it, a translator would first need to allocate memory for the type being translated to, so it could also be that. err -- dtrace_errdata_t -- DTrace Error Data epd -- dtrace_eprobedesc_t -- Enabled Probe Description errpd -- dtrace_probedesc_t -- Error(?) Probe Description It doesn't appear to be the tcp_t structure it's complaining about: # dtrace -n 'tcp:::send { printf("0x%p\n", arg3); } tcp:::send { print(*args[3]); }' dtrace: description 'tcp:::send ' matched 8 probes CPU ID FUNCTION:NAME 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634911292) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634d12292) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634d122e2) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634d12332) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634911292) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff16349112e2) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634911332) in action #1 at DIF offset 416 ^C 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634d12292) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634d122e2) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634d12332) in action #1 at DIF offset 416 1 7187 tcp_send_data:send 0xffffff092a61fb40 dtrace: error on enabled probe ID 6 (ID 7187: tcp:ip:tcp_send_data:send): invalid alignment (0xffffff1634d12382) in action #1 at DIF offset 416 06/05/16 -------- Where is dteda_addr set? $ csgrep.sh dteda_addr Searching for symbol dteda_addr lib/libdtrace/common/dtrace.h:285: () uint64_t dteda_addr; lib/libdtrace/common/dt_handle.c:182: (dt_handle_err) err.dteda_addr = DT_REC(uint64_t, 4); lib/libdtrace/common/dt_handle.c:209: (dt_handle_err) (u_longlong_t)err.dteda_addr); lib/libdtrace/common/dt_handle.c:250: (dt_handle_liberr) err.dteda_addr = NULL; lib/libdtrace_jni/common/dtj_consume.c:304: (dtj_errhandler) addr = data->dteda_addr; In dt_handle_err() it's read as the 4th record in the probe data: DT_REC(uint64_t, 4). But where is the record set? I grep'd for "fault" in uts/common/dtrace and found the epicenter of dtrace: dtrace_probe(). This function checks for faults and then calls dtrace_probe_error(). This is the dtrace-provider error probe. http://dtrace.org/guide/chp-dtrace.html#chp-dtrace-error So if I can trace where it gets the value for arg5 I should be able to figure out what writes the address and where it's coming from. So arg5 comes from the last argument to dtrace_probe_error(): cpu_core[cpuid].cpuc_dtrace_illval How is that set? $ csgrep.sh cpuc_dtrace_illval Searching for symbol cpuc_dtrace_illval uts/common/dtrace/dtrace.c:369: (DTRACE_ALIGNCHECK) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = addr; \ uts/common/dtrace/dtrace.c:423: (DTRACE_LOADFUNC) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = addr; \ uts/common/dtrace/dtrace.c:717: (dtrace_canload) volatile uintptr_t *illval = &cpu_core[CPU->cpu_id].cpuc_dtrace_illval; uts/common/dtrace/dtrace.c:1018: (dtrace_istoxic) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = kaddr; uts/common/dtrace/dtrace.c:1024: (dtrace_istoxic) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = taddr; uts/common/dtrace/dtrace.c:3093: (dtrace_dif_variable) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = NULL; uts/common/dtrace/dtrace.c:3899: (dtrace_dif_subr) volatile uintptr_t *illval = &cpu_core[CPU->cpu_id].cpuc_dtrace_illval; uts/common/dtrace/dtrace.c:5560: (dtrace_dif_emulate) volatile uintptr_t *illval = &cpu_core[CPU->cpu_id].cpuc_dtrace_illval; uts/common/dtrace/dtrace.c:7256: (dtrace_probe) cpu_core[cpuid].cpuc_dtrace_illval); uts/common/dtrace/dtrace.c:14453: (dtrace_helper_trace) ent->dtht_illval = cpu_core[CPU->cpu_id].cpuc_dtrace_illval; uts/common/sys/cpuvar.h:260: (defined) uintptr_t cpuc_dtrace_illval; uts/intel/dtrace/dtrace_isa.c:144: (dtrace_getustack_common) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = sp; uts/intel/dtrace/dtrace_isa.c:194: (dtrace_getustack_common) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = sp; uts/intel/dtrace/dtrace_isa.c:661: (dtrace_copycheck) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = uaddr; uts/intel/dtrace/dtrace_isa.c:708: (dtrace_fuword8) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = (uintptr_t)uaddr; uts/intel/dtrace/dtrace_isa.c:720: (dtrace_fuword16) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = (uintptr_t)uaddr; uts/intel/dtrace/dtrace_isa.c:732: (dtrace_fuword32) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = (uintptr_t)uaddr; uts/intel/dtrace/dtrace_isa.c:744: (dtrace_fuword64) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = (uintptr_t)uaddr; uts/sparc/dtrace/dtrace_isa.c:396: (dtrace_getustack_common) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = sp; uts/sparc/dtrace/dtrace_isa.c:433: (dtrace_getustack_common) cpu_core[CPU->cpu_id].cpuc_dtrace_illval = sp; It's set in a fair amount of areas but I only see one place where CPU_DTRACE_BADALIGN is used: DTRACE_ALIGNCHECK. Which is used by the dtrace_load*() functions, the dtrace_loadptr macro, and dtrace_dif_emulate(). I find one in particular interesting: dtrace_canload(). It sounds like it's related to addresses. It's also interesting because it makes a call to dtrace_canstore() which has this comment: /* * Check to see if the address is within a memory region to which a store may * be issued. This includes the DTrace scratch areas, and any DTrace variable * region. The caller of dtrace_canstore() is responsible for performing any * alignment checks that are needed before stores are actually executed. */ I decided to go back when the print() action was added. https://github.com/illumos/illumos-gate/commit/deef35fd18fdfb1c42002a4793ebb2c181b08680#diff-dad8fb9f721cb61b1ed1b11f5f5bca2f There is a comment that says it is basically the trace() action but passes around the CTF ID for later lookup. If sets it's dta_kind as DTRACEACT_DIFEXPR. dtsd_strdata is related to print() somehow. 06/10/16 -------- The notes for dtps_getargval() (sys/dtrace.h) are interesting. If it's 5th argument is non-NULL it will walk the stack to get the arg value. I wonder if perhaps that's the memory address that is unaligned? If a probe's module and function name are NULL (see dtrace_probe_create) then they are said to be unanchored. Unanchored probes are not associated with a paritcular point in text (see dtrace_impl.h). ECB is Enabling Control Block, and a probe may have many ECBs attached to it. An ECB points to consumer state, an optional list of predicates, and actions. > The ECB abstraction allows a single probe to be multiplexed across > disjoint consumers, or across disjoint enablings of a single probe > within one consumer. See dtrace_impl.h You can debug dtrace helper actions if you set dtrace_helptrace_enabled and then use ::dtrace_helptrace in MDB.