Date: Fri, 19 Jul 2013 00:12:42 +0000 (UTC) From: Scott Long <scottl@FreeBSD.org> To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r253460 - head/sys/dev/mps Message-ID: <201307190012.r6J0Cg1r027645@svn.freebsd.org>
next in thread | raw e-mail | index | archive | help
Author: scottl Date: Fri Jul 19 00:12:41 2013 New Revision: 253460 URL: http://svnweb.freebsd.org/changeset/base/253460 Log: Overhaul error, information, and debug logging. Obtained from: Netflix MFC after: 3 days Modified: head/sys/dev/mps/mps.c head/sys/dev/mps/mps_mapping.c head/sys/dev/mps/mps_pci.c head/sys/dev/mps/mps_sas.c head/sys/dev/mps/mps_sas_lsi.c head/sys/dev/mps/mps_table.c head/sys/dev/mps/mps_user.c head/sys/dev/mps/mpsvar.h Modified: head/sys/dev/mps/mps.c ============================================================================== --- head/sys/dev/mps/mps.c Thu Jul 18 23:25:57 2013 (r253459) +++ head/sys/dev/mps/mps.c Fri Jul 19 00:12:41 2013 (r253460) @@ -81,7 +81,8 @@ static int mps_transition_operational(st static void mps_startup(void *arg); static int mps_send_iocinit(struct mps_softc *sc); static int mps_attach_log(struct mps_softc *sc); -static __inline void mps_complete_command(struct mps_command *cm); +static __inline void mps_complete_command(struct mps_softc *sc, + struct mps_command *cm); static void mps_dispatch_event(struct mps_softc *sc, uintptr_t data, MPI2_EVENT_NOTIFICATION_REPLY *reply); static void mps_config_complete(struct mps_softc *sc, struct mps_command *cm); @@ -195,7 +196,7 @@ static int mps_message_unit_reset(struct mps_softc *sc, int sleep_flag) { - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); mps_regwrite(sc, MPI2_DOORBELL_OFFSET, MPI2_FUNCTION_IOC_MESSAGE_UNIT_RESET << @@ -217,14 +218,14 @@ mps_transition_ready(struct mps_softc *s int error, tries = 0; int sleep_flags; - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); /* If we are in attach call, do not sleep */ sleep_flags = (sc->mps_flags & MPS_FLAGS_ATTACH_DONE) ? CAN_SLEEP:NO_SLEEP; error = 0; while (tries++ < 5) { reg = mps_regread(sc, MPI2_DOORBELL_OFFSET); - mps_dprint(sc, MPS_INFO, "Doorbell= 0x%x\n", reg); + mps_dprint(sc, MPS_INIT, "Doorbell= 0x%x\n", reg); /* * Ensure the IOC is ready to talk. If it's not, try @@ -250,7 +251,7 @@ mps_transition_ready(struct mps_softc *s error = 0; break; } else if (state == MPI2_IOC_STATE_FAULT) { - mps_dprint(sc, MPS_INFO, "IOC in fault state 0x%x\n", + mps_dprint(sc, MPS_FAULT, "IOC in fault state 0x%x, resetting\n", state & MPI2_DOORBELL_FAULT_CODE_MASK); mps_diag_reset(sc, sleep_flags); } else if (state == MPI2_IOC_STATE_OPERATIONAL) { @@ -283,11 +284,11 @@ mps_transition_operational(struct mps_so uint32_t reg, state; int error; - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); error = 0; reg = mps_regread(sc, MPI2_DOORBELL_OFFSET); - mps_dprint(sc, MPS_INFO, "Doorbell= 0x%x\n", reg); + mps_dprint(sc, MPS_INIT, "Doorbell= 0x%x\n", reg); state = reg & MPI2_IOC_STATE_MASK; if (state != MPI2_IOC_STATE_READY) { @@ -318,25 +319,28 @@ mps_reinit(struct mps_softc *sc) int error; uint32_t db; - mps_printf(sc, "%s sc %p\n", __func__, sc); + MPS_FUNCTRACE(sc); mtx_assert(&sc->mps_mtx, MA_OWNED); if (sc->mps_flags & MPS_FLAGS_DIAGRESET) { - mps_printf(sc, "%s reset already in progress\n", __func__); + mps_dprint(sc, MPS_INIT, "%s reset already in progress\n", + __func__); return 0; } + mps_dprint(sc, MPS_INFO, "Reinitializing controller,\n"); /* make sure the completion callbacks can recognize they're getting * a NULL cm_reply due to a reset. */ sc->mps_flags |= MPS_FLAGS_DIAGRESET; - mps_printf(sc, "%s mask interrupts\n", __func__); + mps_dprint(sc, MPS_INIT, "%s mask interrupts\n", __func__); mps_mask_intr(sc); error = mps_diag_reset(sc, CAN_SLEEP); if (error != 0) { + /* XXXSL No need to panic here */ panic("%s hard reset failed with error %d\n", __func__, error); } @@ -354,6 +358,7 @@ mps_reinit(struct mps_softc *sc) /* get the chip out of the reset state */ error = mps_transition_operational(sc); if (error != 0) + /* XXXSL No need to panic here */ panic("%s transition operational failed with error %d\n", __func__, error); @@ -368,14 +373,14 @@ mps_reinit(struct mps_softc *sc) mps_regwrite(sc, MPI2_REPLY_POST_HOST_INDEX_OFFSET, sc->replypostindex); db = mps_regread(sc, MPI2_DOORBELL_OFFSET); - mps_printf(sc, "%s doorbell 0x%08x\n", __func__, db); + mps_dprint(sc, MPS_INIT, "%s doorbell 0x%08x\n", __func__, db); - mps_printf(sc, "%s unmask interrupts post %u free %u\n", __func__, - sc->replypostindex, sc->replyfreeindex); + mps_dprint(sc, MPS_INIT, "%s unmask interrupts post %u free %u\n", + __func__, sc->replypostindex, sc->replyfreeindex); mps_unmask_intr(sc); - mps_printf(sc, "%s restarting post %u free %u\n", __func__, + mps_dprint(sc, MPS_INIT, "%s restarting post %u free %u\n", __func__, sc->replypostindex, sc->replyfreeindex); /* restart will reload the event masks clobbered by the reset, and @@ -384,9 +389,8 @@ mps_reinit(struct mps_softc *sc) mps_reregister_events(sc); /* the end of discovery will release the simq, so we're done. */ - mps_printf(sc, "%s finished sc %p post %u free %u\n", - __func__, sc, - sc->replypostindex, sc->replyfreeindex); + mps_dprint(sc, MPS_INFO, "%s finished sc %p post %u free %u\n", + __func__, sc, sc->replypostindex, sc->replyfreeindex); sc->mps_flags &= ~MPS_FLAGS_DIAGRESET; @@ -411,7 +415,7 @@ mps_wait_db_ack(struct mps_softc *sc, in do { int_status = mps_regread(sc, MPI2_HOST_INTERRUPT_STATUS_OFFSET); if (!(int_status & MPI2_HIS_SYS2IOC_DB_STATUS)) { - mps_dprint(sc, MPS_INFO, + mps_dprint(sc, MPS_INIT, "%s: successfull count(%d), timeout(%d)\n", __func__, count, timeout); return 0; @@ -546,7 +550,7 @@ mps_request_sync(struct mps_softc *sc, v count = MIN((reply_sz / 4), ioc_sz) * 2; if (count < ioc_sz * 2) { residual = ioc_sz * 2 - count; - mps_dprint(sc, MPS_FAULT, "Driver error, throwing away %d " + mps_dprint(sc, MPS_ERROR, "Driver error, throwing away %d " "residual message words\n", residual); } @@ -592,7 +596,8 @@ static void mps_enqueue_request(struct mps_softc *sc, struct mps_command *cm) { reply_descriptor rd; - mps_dprint(sc, MPS_TRACE, "%s SMID %u cm %p ccb %p\n", __func__, + MPS_FUNCTRACE(sc); + mps_dprint(sc, MPS_TRACE, "SMID %u cm %p ccb %p\n", cm->cm_desc.Default.SMID, cm, cm->cm_ccb); if (sc->mps_flags & MPS_FLAGS_ATTACH_DONE && !(sc->mps_flags & MPS_FLAGS_SHUTDOWN)) @@ -620,7 +625,7 @@ mps_get_iocfacts(struct mps_softc *sc, M MPI2_IOC_FACTS_REQUEST request; int error, req_sz, reply_sz; - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); req_sz = sizeof(MPI2_IOC_FACTS_REQUEST); reply_sz = sizeof(MPI2_IOC_FACTS_REPLY); @@ -641,7 +646,7 @@ mps_get_portfacts(struct mps_softc *sc, struct mps_command *cm; int error; - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); if ((cm = mps_alloc_command(sc)) == NULL) return (EBUSY); @@ -677,7 +682,7 @@ mps_send_iocinit(struct mps_softc *sc) MPI2_DEFAULT_REPLY reply; int req_sz, reply_sz, error; - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); req_sz = sizeof(MPI2_IOC_INIT_REQUEST); reply_sz = sizeof(MPI2_IOC_INIT_REPLY); @@ -711,7 +716,7 @@ mps_send_iocinit(struct mps_softc *sc) if ((reply.IOCStatus & MPI2_IOCSTATUS_MASK) != MPI2_IOCSTATUS_SUCCESS) error = ENXIO; - mps_dprint(sc, MPS_INFO, "IOCInit status= 0x%x\n", reply.IOCStatus); + mps_dprint(sc, MPS_INIT, "IOCInit status= 0x%x\n", reply.IOCStatus); return (error); } @@ -1008,7 +1013,7 @@ mps_get_tunables(struct mps_softc *sc) char tmpstr[80]; /* XXX default to some debugging for now */ - sc->mps_debug = MPS_FAULT; + sc->mps_debug = MPS_INFO|MPS_FAULT; sc->disable_msix = 0; sc->disable_msi = 0; sc->max_chains = MPS_CHAIN_FRAMES; @@ -1123,7 +1128,7 @@ mps_attach(struct mps_softc *sc) mps_get_tunables(sc); - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); mtx_init(&sc->mps_mtx, "MPT2SAS lock", NULL, MTX_DEF); callout_init_mtx(&sc->periodic, &sc->mps_mtx, 0); @@ -1297,7 +1302,7 @@ mps_attach(struct mps_softc *sc) sc->mps_ich.ich_func = mps_startup; sc->mps_ich.ich_arg = sc; if (config_intrhook_establish(&sc->mps_ich) != 0) { - mps_dprint(sc, MPS_FAULT, "Cannot establish MPS config hook\n"); + mps_dprint(sc, MPS_ERROR, "Cannot establish MPS config hook\n"); error = EINVAL; } @@ -1308,7 +1313,7 @@ mps_attach(struct mps_softc *sc) mpssas_ir_shutdown, sc, SHUTDOWN_PRI_DEFAULT); if (sc->shutdown_eh == NULL) - mps_dprint(sc, MPS_FAULT, "shutdown event registration " + mps_dprint(sc, MPS_ERROR, "shutdown event registration " "failed\n"); mps_setup_sysctl(sc); @@ -1347,8 +1352,7 @@ mps_periodic(void *arg) db = mps_regread(sc, MPI2_DOORBELL_OFFSET); if ((db & MPI2_IOC_STATE_MASK) == MPI2_IOC_STATE_FAULT) { - device_printf(sc->mps_dev, "IOC Fault 0x%08x, Resetting\n", db); - + mps_dprint(sc, MPS_FAULT, "IOC Fault 0x%08x, Resetting\n", db); mps_reinit(sc); } @@ -1365,12 +1369,13 @@ mps_log_evt_handler(struct mps_softc *sc switch (event->Event) { case MPI2_EVENT_LOG_DATA: - device_printf(sc->mps_dev, "MPI2_EVENT_LOG_DATA:\n"); - hexdump(event->EventData, event->EventDataLength, NULL, 0); + mps_dprint(sc, MPS_EVENT, "MPI2_EVENT_LOG_DATA:\n"); + if (sc->mps_debug & MPS_EVENT) + hexdump(event->EventData, event->EventDataLength, NULL, 0); break; case MPI2_EVENT_LOG_ENTRY_ADDED: entry = (MPI2_EVENT_DATA_LOG_ENTRY_ADDED *)event->EventData; - mps_dprint(sc, MPS_INFO, "MPI2_EVENT_LOG_ENTRY_ADDED event " + mps_dprint(sc, MPS_EVENT, "MPI2_EVENT_LOG_ENTRY_ADDED event " "0x%x Sequence %d:\n", entry->LogEntryQualifier, entry->LogSequence); break; @@ -1504,29 +1509,35 @@ mps_free(struct mps_softc *sc) } static __inline void -mps_complete_command(struct mps_command *cm) +mps_complete_command(struct mps_softc *sc, struct mps_command *cm) { + MPS_FUNCTRACE(sc); + + if (cm == NULL) { + mps_dprint(sc, MPS_ERROR, "Completing NULL command\n"); + return; + } + if (cm->cm_flags & MPS_CM_FLAGS_POLLED) cm->cm_flags |= MPS_CM_FLAGS_COMPLETE; if (cm->cm_complete != NULL) { - mps_dprint(cm->cm_sc, MPS_TRACE, + mps_dprint(sc, MPS_TRACE, "%s cm %p calling cm_complete %p data %p reply %p\n", __func__, cm, cm->cm_complete, cm->cm_complete_data, cm->cm_reply); - cm->cm_complete(cm->cm_sc, cm); + cm->cm_complete(sc, cm); } if (cm->cm_flags & MPS_CM_FLAGS_WAKEUP) { - mps_dprint(cm->cm_sc, MPS_TRACE, "%s: waking up %p\n", - __func__, cm); + mps_dprint(sc, MPS_TRACE, "waking up %p\n", cm); wakeup(cm); } if (cm->cm_sc->io_cmds_active != 0) { cm->cm_sc->io_cmds_active--; } else { - mps_dprint(cm->cm_sc, MPS_INFO, "Warning: io_cmds_active is " + mps_dprint(sc, MPS_ERROR, "Warning: io_cmds_active is " "out of sync - resynching to 0\n"); } } @@ -1572,7 +1583,7 @@ mps_sas_log_info(struct mps_softc *sc , break; } - mps_dprint(sc, MPS_INFO, "log_info(0x%08x): originator(%s), " + mps_dprint(sc, MPS_LOG, "log_info(0x%08x): originator(%s), " "code(0x%02x), sub_code(0x%04x)\n", log_info, originator_str, sas_loginfo.dw.code, sas_loginfo.dw.subcode); @@ -1750,7 +1761,7 @@ mps_intr_locked(void *data) case MPI2_RPY_DESCRIPT_FLAGS_RAID_ACCELERATOR_SUCCESS: default: /* Unhandled */ - device_printf(sc->mps_dev, "Unhandled reply 0x%x\n", + mps_dprint(sc, MPS_ERROR, "Unhandled reply 0x%x\n", desc->Default.ReplyFlags); cm = NULL; break; @@ -1761,7 +1772,7 @@ mps_intr_locked(void *data) // Print Error reply frame if (cm->cm_reply) mps_display_reply_info(sc,cm->cm_reply); - mps_complete_command(cm); + mps_complete_command(sc, cm); } desc->Words.Low = 0xffffffff; @@ -1794,7 +1805,7 @@ mps_dispatch_event(struct mps_softc *sc, } if (handled == 0) - device_printf(sc->mps_dev, "Unhandled event 0x%x\n", le16toh(event)); + mps_dprint(sc, MPS_EVENT, "Unhandled event 0x%x\n", le16toh(event)); /* * This is the only place that the event/reply should be freed. @@ -2197,7 +2208,8 @@ mps_data_cb(void *arg, bus_dma_segment_t * user they did the wrong thing. */ if ((cm->cm_max_segs != 0) && (nsegs > cm->cm_max_segs)) { - mps_printf(sc, "%s: warning: busdma returned %d segments, " + mps_dprint(sc, MPS_ERROR, + "%s: warning: busdma returned %d segments, " "more than the %d allowed\n", __func__, nsegs, cm->cm_max_segs); } @@ -2243,9 +2255,10 @@ mps_data_cb(void *arg, bus_dma_segment_t sflags, nsegs - i); if (error != 0) { /* Resource shortage, roll back! */ - mps_dprint(sc, MPS_INFO, "out of chain frames\n"); + mps_dprint(sc, MPS_INFO, "Out of chain frames, " + "consider increasing hw.mps.max_chains.\n"); cm->cm_flags |= MPS_CM_FLAGS_CHAIN_FAILED; - mps_complete_command(cm); + mps_complete_command(sc, cm); return; } } @@ -2444,6 +2457,7 @@ mps_config_complete(struct mps_softc *sc MPI2_CONFIG_REPLY *reply; struct mps_config_params *params; + MPS_FUNCTRACE(sc); params = cm->cm_complete_data; if (cm->cm_data != NULL) { Modified: head/sys/dev/mps/mps_mapping.c ============================================================================== --- head/sys/dev/mps/mps_mapping.c Thu Jul 18 23:25:57 2013 (r253459) +++ head/sys/dev/mps/mps_mapping.c Fri Jul 19 00:12:41 2013 (r253460) @@ -927,8 +927,9 @@ _mapping_get_dev_info(struct mps_softc * sas_address = (sas_address << 32) | sas_device_pg0.SASAddress.Low; } - mps_dprint(sc, MPS_INFO, "SAS Address for SATA " - "device = %jx\n", sas_address); + mps_dprint(sc, MPS_MAPPING, + "SAS Address for SATA device = %jx\n", + sas_address); } else { sas_address = sas_device_pg0.SASAddress.High; Modified: head/sys/dev/mps/mps_pci.c ============================================================================== --- head/sys/dev/mps/mps_pci.c Thu Jul 18 23:25:57 2013 (r253459) +++ head/sys/dev/mps/mps_pci.c Fri Jul 19 00:12:41 2013 (r253460) @@ -198,11 +198,11 @@ mps_pci_attach(device_t dev) pci_write_config(dev, PCIR_COMMAND, command, 2); command = pci_read_config(dev, PCIR_COMMAND, 2); if ((command & PCIM_CMD_BUSMASTEREN) == 0) { - device_printf(dev, "Cannot enable PCI busmaster\n"); + mps_printf(sc, "Cannot enable PCI busmaster\n"); return (ENXIO); } if ((command & PCIM_CMD_MEMEN) == 0) { - device_printf(dev, "PCI memory window not available\n"); + mps_printf(sc, "PCI memory window not available\n"); return (ENXIO); } @@ -210,7 +210,7 @@ mps_pci_attach(device_t dev) sc->mps_regs_rid = PCIR_BAR(1); if ((sc->mps_regs_resource = bus_alloc_resource_any(dev, SYS_RES_MEMORY, &sc->mps_regs_rid, RF_ACTIVE)) == NULL) { - device_printf(dev, "Cannot allocate PCI registers\n"); + mps_printf(sc, "Cannot allocate PCI registers\n"); return (ENXIO); } sc->mps_btag = rman_get_bustag(sc->mps_regs_resource); @@ -228,7 +228,7 @@ mps_pci_attach(device_t dev) 0, /* flags */ NULL, NULL, /* lockfunc, lockarg */ &sc->mps_parent_dmat)) { - device_printf(dev, "Cannot allocate parent DMA tag\n"); + mps_printf(sc, "Cannot allocate parent DMA tag\n"); mps_pci_free(sc); return (ENOMEM); } @@ -260,14 +260,14 @@ mps_pci_setup_interrupts(struct mps_soft sc->mps_irq[0] = bus_alloc_resource_any(dev, SYS_RES_IRQ, &sc->mps_irq_rid[0], RF_SHAREABLE | RF_ACTIVE); if (sc->mps_irq[0] == NULL) { - device_printf(dev, "Cannot allocate INTx interrupt\n"); + mps_printf(sc, "Cannot allocate INTx interrupt\n"); return (ENXIO); } error = bus_setup_intr(dev, sc->mps_irq[0], INTR_TYPE_BIO | INTR_MPSAFE, NULL, mps_intr, sc, &sc->mps_intrhand[0]); if (error) - device_printf(dev, "Cannot setup INTx interrupt\n"); + mps_printf(sc, "Cannot setup INTx interrupt\n"); } else { sc->mps_flags |= MPS_FLAGS_MSI; for (i = 0; i < MPS_MSI_COUNT; i++) { @@ -275,7 +275,7 @@ mps_pci_setup_interrupts(struct mps_soft sc->mps_irq[i] = bus_alloc_resource_any(dev, SYS_RES_IRQ, &sc->mps_irq_rid[i], RF_ACTIVE); if (sc->mps_irq[i] == NULL) { - device_printf(dev, + mps_printf(sc, "Cannot allocate MSI interrupt\n"); return (ENXIO); } @@ -283,7 +283,7 @@ mps_pci_setup_interrupts(struct mps_soft INTR_TYPE_BIO | INTR_MPSAFE, NULL, mps_intr_msi, sc, &sc->mps_intrhand[i]); if (error) { - device_printf(dev, + mps_printf(sc, "Cannot setup MSI interrupt %d\n", i); break; } Modified: head/sys/dev/mps/mps_sas.c ============================================================================== --- head/sys/dev/mps/mps_sas.c Thu Jul 18 23:25:57 2013 (r253459) +++ head/sys/dev/mps/mps_sas.c Fri Jul 19 00:12:41 2013 (r253460) @@ -175,14 +175,16 @@ mpssas_find_target_by_handle(struct mpss void mpssas_startup_increment(struct mpssas_softc *sassc) { + MPS_FUNCTRACE(sassc->sc); + if ((sassc->flags & MPSSAS_IN_STARTUP) != 0) { if (sassc->startup_refcount++ == 0) { /* just starting, freeze the simq */ - mps_dprint(sassc->sc, MPS_INFO, + mps_dprint(sassc->sc, MPS_INIT, "%s freezing simq\n", __func__); xpt_freeze_simq(sassc->sim, 1); } - mps_dprint(sassc->sc, MPS_TRACE, "%s refcount %u\n", __func__, + mps_dprint(sassc->sc, MPS_INIT, "%s refcount %u\n", __func__, sassc->startup_refcount); } } @@ -190,18 +192,20 @@ mpssas_startup_increment(struct mpssas_s void mpssas_startup_decrement(struct mpssas_softc *sassc) { + MPS_FUNCTRACE(sassc->sc); + if ((sassc->flags & MPSSAS_IN_STARTUP) != 0) { if (--sassc->startup_refcount == 0) { /* finished all discovery-related actions, release * the simq and rescan for the latest topology. */ - mps_dprint(sassc->sc, MPS_INFO, + mps_dprint(sassc->sc, MPS_INIT, "%s releasing simq\n", __func__); sassc->flags &= ~MPSSAS_IN_STARTUP; xpt_release_simq(sassc->sim, 1); mpssas_rescan_target(sassc->sc, NULL); } - mps_dprint(sassc->sc, MPS_TRACE, "%s refcount %u\n", __func__, + mps_dprint(sassc->sc, MPS_INIT, "%s refcount %u\n", __func__, sassc->startup_refcount); } } @@ -215,13 +219,15 @@ mpssas_alloc_tm(struct mps_softc *sc) { struct mps_command *tm; + MPS_FUNCTRACE(sc); tm = mps_alloc_high_priority_command(sc); if (tm != NULL) { if (sc->sassc->tm_count++ == 0) { - mps_printf(sc, "%s freezing simq\n", __func__); + mps_dprint(sc, MPS_RECOVERY, + "%s freezing simq\n", __func__); xpt_freeze_simq(sc->sassc->sim, 1); } - mps_dprint(sc, MPS_TRACE, "%s tm_count %u\n", __func__, + mps_dprint(sc, MPS_RECOVERY, "%s tm_count %u\n", __func__, sc->sassc->tm_count); } return tm; @@ -230,6 +236,7 @@ mpssas_alloc_tm(struct mps_softc *sc) void mpssas_free_tm(struct mps_softc *sc, struct mps_command *tm) { + mps_dprint(sc, MPS_TRACE, "%s", __func__); if (tm == NULL) return; @@ -238,10 +245,10 @@ mpssas_free_tm(struct mps_softc *sc, str * release the simq. */ if (--sc->sassc->tm_count == 0) { - mps_printf(sc, "%s releasing simq\n", __func__); + mps_dprint(sc, MPS_RECOVERY, "%s releasing simq\n", __func__); xpt_release_simq(sc->sassc->sim, 1); } - mps_dprint(sc, MPS_TRACE, "%s tm_count %u\n", __func__, + mps_dprint(sc, MPS_RECOVERY, "%s tm_count %u\n", __func__, sc->sassc->tm_count); mps_free_high_priority_command(sc, tm); @@ -256,6 +263,7 @@ mpssas_rescan_target(struct mps_softc *s target_id_t targetid; union ccb *ccb; + MPS_FUNCTRACE(sc); pathid = cam_sim_path(sassc->sim); if (targ == NULL) targetid = CAM_TARGET_WILDCARD; @@ -267,13 +275,13 @@ mpssas_rescan_target(struct mps_softc *s */ ccb = xpt_alloc_ccb_nowait(); if (ccb == NULL) { - mps_dprint(sc, MPS_FAULT, "unable to alloc CCB for rescan\n"); + mps_dprint(sc, MPS_ERROR, "unable to alloc CCB for rescan\n"); return; } if (xpt_create_path(&ccb->ccb_h.path, NULL, pathid, targetid, CAM_LUN_WILDCARD) != CAM_REQ_CMP) { - mps_dprint(sc, MPS_FAULT, "unable to create path for rescan\n"); + mps_dprint(sc, MPS_ERROR, "unable to create path for rescan\n"); xpt_free_ccb(ccb); return; } @@ -288,7 +296,7 @@ mpssas_rescan_target(struct mps_softc *s } static void -mpssas_log_command(struct mps_command *cm, const char *fmt, ...) +mpssas_log_command(struct mps_command *cm, u_int level, const char *fmt, ...) { struct sbuf sb; va_list ap; @@ -324,7 +332,7 @@ mpssas_log_command(struct mps_command *c sbuf_printf(&sb, "SMID %u ", cm->cm_desc.Default.SMID); sbuf_vprintf(&sb, fmt, ap); sbuf_finish(&sb); - printf("%s", sbuf_data(&sb)); + mps_dprint_field(cm->cm_sc, level, "%s", sbuf_data(&sb)); va_end(ap); } @@ -337,7 +345,7 @@ mpssas_remove_volume(struct mps_softc *s struct mpssas_target *targ; uint16_t handle; - mps_dprint(sc, MPS_INFO, "%s\n", __func__); + MPS_FUNCTRACE(sc); reply = (MPI2_SCSI_TASK_MANAGE_REPLY *)tm->cm_reply; handle = (uint16_t)(uintptr_t)tm->cm_complete_data; @@ -345,24 +353,27 @@ mpssas_remove_volume(struct mps_softc *s if (reply == NULL) { /* XXX retry the remove after the diag reset completes? */ - mps_printf(sc, "%s NULL reply reseting device 0x%04x\n", - __func__, handle); + mps_dprint(sc, MPS_FAULT, + "%s NULL reply reseting device 0x%04x\n", __func__, handle); mpssas_free_tm(sc, tm); return; } if (reply->IOCStatus != MPI2_IOCSTATUS_SUCCESS) { - mps_printf(sc, "IOCStatus = 0x%x while resetting device 0x%x\n", + mps_dprint(sc, MPS_FAULT, + "IOCStatus = 0x%x while resetting device 0x%x\n", reply->IOCStatus, handle); mpssas_free_tm(sc, tm); return; } - mps_printf(sc, "Reset aborted %u commands\n", reply->TerminationCount); + mps_dprint(sc, MPS_XINFO, + "Reset aborted %u commands\n", reply->TerminationCount); mps_free_reply(sc, tm->cm_reply_data); tm->cm_reply = NULL; /* Ensures the reply won't get re-freed */ - mps_printf(sc, "clearing target %u handle 0x%04x\n", targ->tid, handle); + mps_dprint(sc, MPS_XINFO, + "clearing target %u handle 0x%04x\n", targ->tid, handle); /* * Don't clear target if remove fails because things will get confusing. @@ -398,7 +409,7 @@ mpssas_prepare_volume_remove(struct mpss struct mps_command *cm; struct mpssas_target *targ = NULL; - mps_dprint(sassc->sc, MPS_INFO, "%s\n", __func__); + MPS_FUNCTRACE(sassc->sc); sc = sassc->sc; #ifdef WD_SUPPORT @@ -417,7 +428,8 @@ mpssas_prepare_volume_remove(struct mpss if (targ == NULL) { /* FIXME: what is the action? */ /* We don't know about this device? */ - printf("%s %d : invalid handle 0x%x \n", __func__,__LINE__, handle); + mps_dprint(sc, MPS_ERROR, + "%s %d : invalid handle 0x%x \n", __func__,__LINE__, handle); return; } @@ -425,7 +437,8 @@ mpssas_prepare_volume_remove(struct mpss cm = mpssas_alloc_tm(sc); if (cm == NULL) { - mps_printf(sc, "%s: command alloc failure\n", __func__); + mps_dprint(sc, MPS_ERROR, + "%s: command alloc failure\n", __func__); return; } @@ -465,7 +478,7 @@ mpssas_prepare_remove(struct mpssas_soft struct mps_command *cm; struct mpssas_target *targ = NULL; - mps_dprint(sassc->sc, MPS_INFO, "%s\n", __func__); + MPS_FUNCTRACE(sassc->sc); sc = sassc->sc; @@ -473,7 +486,8 @@ mpssas_prepare_remove(struct mpssas_soft if (targ == NULL) { /* FIXME: what is the action? */ /* We don't know about this device? */ - printf("%s %d : invalid handle 0x%x \n", __func__,__LINE__, handle); + mps_dprint(sc, MPS_ERROR, + "%s : invalid handle 0x%x \n", __func__, handle); return; } @@ -481,7 +495,8 @@ mpssas_prepare_remove(struct mpssas_soft cm = mpssas_alloc_tm(sc); if (cm == NULL) { - mps_printf(sc, "%s: command alloc failure\n", __func__); + mps_dprint(sc, MPS_ERROR, + "%s: command alloc failure\n", __func__); return; } @@ -513,7 +528,7 @@ mpssas_remove_device(struct mps_softc *s struct mps_command *next_cm; uint16_t handle; - mps_dprint(sc, MPS_INFO, "%s\n", __func__); + MPS_FUNCTRACE(sc); reply = (MPI2_SCSI_TASK_MANAGE_REPLY *)tm->cm_reply; handle = (uint16_t)(uintptr_t)tm->cm_complete_data; @@ -525,29 +540,31 @@ mpssas_remove_device(struct mps_softc *s * task management commands don't have S/G lists. */ if ((tm->cm_flags & MPS_CM_FLAGS_ERROR_MASK) != 0) { - mps_printf(sc, "%s: cm_flags = %#x for remove of handle %#04x! " - "This should not happen!\n", __func__, tm->cm_flags, - handle); + mps_dprint(sc, MPS_ERROR, + "%s: cm_flags = %#x for remove of handle %#04x! " + "This should not happen!\n", __func__, tm->cm_flags, + handle); mpssas_free_tm(sc, tm); return; } if (reply == NULL) { /* XXX retry the remove after the diag reset completes? */ - mps_printf(sc, "%s NULL reply reseting device 0x%04x\n", - __func__, handle); + mps_dprint(sc, MPS_FAULT, + "%s NULL reply reseting device 0x%04x\n", __func__, handle); mpssas_free_tm(sc, tm); return; } if (le16toh(reply->IOCStatus) != MPI2_IOCSTATUS_SUCCESS) { - mps_printf(sc, "IOCStatus = 0x%x while resetting device 0x%x\n", + mps_dprint(sc, MPS_FAULT, + "IOCStatus = 0x%x while resetting device 0x%x\n", le16toh(reply->IOCStatus), handle); mpssas_free_tm(sc, tm); return; } - mps_dprint(sc, MPS_INFO, "Reset aborted %u commands\n", + mps_dprint(sc, MPS_XINFO, "Reset aborted %u commands\n", le32toh(reply->TerminationCount)); mps_free_reply(sc, tm->cm_reply_data); tm->cm_reply = NULL; /* Ensures the reply won't get re-freed */ @@ -565,12 +582,12 @@ mpssas_remove_device(struct mps_softc *s mps_map_command(sc, tm); - mps_dprint(sc, MPS_INFO, "clearing target %u handle 0x%04x\n", + mps_dprint(sc, MPS_XINFO, "clearing target %u handle 0x%04x\n", targ->tid, handle); TAILQ_FOREACH_SAFE(tm, &targ->commands, cm_link, next_cm) { union ccb *ccb; - mps_dprint(sc, MPS_INFO, "Completing missed command %p\n", tm); + mps_dprint(sc, MPS_XINFO, "Completing missed command %p\n", tm); ccb = tm->cm_complete_data; ccb->ccb_h.status = CAM_DEV_NOT_THERE; mpssas_scsiio_complete(sc, tm); @@ -585,7 +602,7 @@ mpssas_remove_complete(struct mps_softc struct mpssas_target *targ; struct mpssas_lun *lun; - mps_dprint(sc, MPS_INFO, "%s\n", __func__); + MPS_FUNCTRACE(sc); reply = (MPI2_SAS_IOUNIT_CONTROL_REPLY *)tm->cm_reply; handle = (uint16_t)(uintptr_t)tm->cm_complete_data; @@ -596,7 +613,8 @@ mpssas_remove_complete(struct mps_softc * task management commands don't have S/G lists. */ if ((tm->cm_flags & MPS_CM_FLAGS_ERROR_MASK) != 0) { - mps_printf(sc, "%s: cm_flags = %#x for remove of handle %#04x! " + mps_dprint(sc, MPS_XINFO, + "%s: cm_flags = %#x for remove of handle %#04x! " "This should not happen!\n", __func__, tm->cm_flags, handle); mpssas_free_tm(sc, tm); @@ -605,13 +623,14 @@ mpssas_remove_complete(struct mps_softc if (reply == NULL) { /* most likely a chip reset */ - mps_printf(sc, "%s NULL reply removing device 0x%04x\n", - __func__, handle); + mps_dprint(sc, MPS_FAULT, + "%s NULL reply removing device 0x%04x\n", __func__, handle); mpssas_free_tm(sc, tm); return; } - mps_printf(sc, "%s on handle 0x%04x, IOCStatus= 0x%x\n", __func__, + mps_dprint(sc, MPS_XINFO, + "%s on handle 0x%04x, IOCStatus= 0x%x\n", __func__, handle, le16toh(reply->IOCStatus)); /* @@ -676,7 +695,7 @@ mps_attach_sas(struct mps_softc *sc) #endif int unit, error = 0; - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); sassc = malloc(sizeof(struct mpssas_softc), M_MPT2, M_WAITOK|M_ZERO); if(!sassc) { @@ -696,7 +715,7 @@ mps_attach_sas(struct mps_softc *sc) sassc->sc = sc; if ((sassc->devq = cam_simq_alloc(sc->num_reqs)) == NULL) { - mps_dprint(sc, MPS_FAULT, "Cannot allocate SIMQ\n"); + mps_dprint(sc, MPS_ERROR, "Cannot allocate SIMQ\n"); error = ENOMEM; goto out; } @@ -705,7 +724,7 @@ mps_attach_sas(struct mps_softc *sc) sassc->sim = cam_sim_alloc(mpssas_action, mpssas_poll, "mps", sassc, unit, &sc->mps_mtx, sc->num_reqs, sc->num_reqs, sassc->devq); if (sassc->sim == NULL) { - mps_dprint(sc, MPS_FAULT, "Cannot allocate SIM\n"); + mps_dprint(sc, MPS_ERROR, "Cannot allocate SIM\n"); error = EINVAL; goto out; } @@ -738,7 +757,7 @@ mps_attach_sas(struct mps_softc *sc) * everything is just a target on a single bus. */ if ((error = xpt_bus_register(sassc->sim, sc->mps_dev, 0)) != 0) { - mps_dprint(sc, MPS_FAULT, "Error %d registering SCSI bus\n", + mps_dprint(sc, MPS_ERROR, "Error %d registering SCSI bus\n", error); mps_unlock(sc); goto out; @@ -761,8 +780,9 @@ mps_attach_sas(struct mps_softc *sc) #if __FreeBSD_version >= 1000006 status = xpt_register_async(AC_ADVINFO_CHANGED, mpssas_async, sc, NULL); if (status != CAM_REQ_CMP) { - mps_printf(sc, "Error %#x registering async handler for " - "AC_ADVINFO_CHANGED events\n", status); + mps_dprint(sc, MPS_ERROR, + "Error %#x registering async handler for " + "AC_ADVINFO_CHANGED events\n", status); } #endif @@ -783,7 +803,7 @@ mps_detach_sas(struct mps_softc *sc) struct mpssas_target *targ; int i; - mps_dprint(sc, MPS_INFO, "%s\n", __func__); + MPS_FUNCTRACE(sc); if (sc->sassc == NULL) return (0); @@ -826,7 +846,6 @@ mps_detach_sas(struct mps_softc *sc) } mps_unlock(sc); - mps_dprint(sc, MPS_INFO, "%s:%d\n", __func__,__LINE__); if (sassc->devq != NULL) cam_simq_free(sassc->devq); @@ -848,7 +867,7 @@ mpssas_discovery_end(struct mpssas_softc { struct mps_softc *sc = sassc->sc; - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); if (sassc->flags & MPSSAS_DISCOVERY_TIMEOUT_PENDING) callout_stop(&sassc->discovery_callout); @@ -862,17 +881,17 @@ mpssas_discovery_timeout(void *data) struct mps_softc *sc; sc = sassc->sc; - mps_dprint(sc, MPS_TRACE, "%s\n", __func__); + MPS_FUNCTRACE(sc); mps_lock(sc); - mps_printf(sc, + mps_dprint(sc, MPS_INFO, "Timeout waiting for discovery, interrupts may not be working!\n"); sassc->flags &= ~MPSSAS_DISCOVERY_TIMEOUT_PENDING; /* Poll the hardware for events in case interrupts aren't working */ mps_intr_locked(sc); - mps_printf(sassc->sc, + mps_dprint(sassc->sc, MPS_INFO, "Finished polling after discovery timeout at %d\n", ticks); if ((sassc->flags & MPSSAS_IN_DISCOVERY) == 0) { @@ -902,7 +921,8 @@ mpssas_action(struct cam_sim *sim, union sassc = cam_sim_softc(sim); - mps_dprint(sassc->sc, MPS_TRACE, "%s func 0x%x\n", __func__, + MPS_FUNCTRACE(sassc->sc); + mps_dprint(sassc->sc, MPS_TRACE, "ccb func_code 0x%x\n", ccb->ccb_h.func_code); mtx_assert(&sassc->sc->mps_mtx, MA_OWNED); @@ -986,14 +1006,14 @@ mpssas_action(struct cam_sim *sim, union ccb->ccb_h.status = CAM_REQ_CMP; break; case XPT_RESET_DEV: - mps_printf(sassc->sc, "mpssas_action XPT_RESET_DEV\n"); + mps_dprint(sassc->sc, MPS_XINFO, "mpssas_action XPT_RESET_DEV\n"); mpssas_action_resetdev(sassc, ccb); return; case XPT_RESET_BUS: case XPT_ABORT: case XPT_TERM_IO: - mps_printf(sassc->sc, "mpssas_action faking success for " - "abort or reset\n"); + mps_dprint(sassc->sc, MPS_XINFO, + "mpssas_action faking success for abort or reset\n"); ccb->ccb_h.status = CAM_REQ_CMP; break; case XPT_SCSI_IO: @@ -1019,12 +1039,12 @@ mpssas_announce_reset(struct mps_softc * path_id_t path_id = cam_sim_path(sc->sassc->sim); struct cam_path *path; - mps_printf(sc, "%s code %x target %d lun %d\n", __func__, + mps_dprint(sc, MPS_XINFO, "%s code %x target %d lun %d\n", __func__, ac_code, target_id, lun_id); if (xpt_create_path(&path, NULL, path_id, target_id, lun_id) != CAM_REQ_CMP) { - mps_printf(sc, "unable to create path for reset " + mps_dprint(sc, MPS_ERROR, "unable to create path for reset " "notification\n"); return; } @@ -1040,7 +1060,7 @@ mpssas_complete_all_commands(struct mps_ int i; int completed; - mps_printf(sc, "%s\n", __func__); + MPS_FUNCTRACE(sc); mtx_assert(&sc->mps_mtx, MA_OWNED); /* complete all commands with a NULL reply */ @@ -1053,7 +1073,7 @@ mpssas_complete_all_commands(struct mps_ cm->cm_flags |= MPS_CM_FLAGS_COMPLETE; if (cm->cm_complete != NULL) { - mpssas_log_command(cm, + mpssas_log_command(cm, MPS_RECOVERY, "completing cm %p state %x ccb %p for diag reset\n", cm, cm->cm_state, cm->cm_ccb); @@ -1062,7 +1082,7 @@ mpssas_complete_all_commands(struct mps_ } if (cm->cm_flags & MPS_CM_FLAGS_WAKEUP) { - mpssas_log_command(cm, + mpssas_log_command(cm, MPS_RECOVERY, "waking up cm %p state %x ccb %p for diag reset\n", cm, cm->cm_state, cm->cm_ccb); wakeup(cm); @@ -1071,7 +1091,7 @@ mpssas_complete_all_commands(struct mps_ if ((completed == 0) && (cm->cm_state != MPS_CM_STATE_FREE)) { /* this should never happen, but if it does, log */ - mpssas_log_command(cm, + mpssas_log_command(cm, MPS_RECOVERY, "cm %p state %x flags 0x%x ccb %p during diag " "reset\n", cm, cm->cm_state, cm->cm_flags, cm->cm_ccb); @@ -1092,7 +1112,7 @@ mpssas_handle_reinit(struct mps_softc *s * discovery-related activities have finished, the simq will be * released. */ - mps_printf(sc, "%s startup\n", __func__); + mps_dprint(sc, MPS_INIT, "%s startup\n", __func__); sc->sassc->flags |= MPSSAS_IN_STARTUP; sc->sassc->flags |= MPSSAS_IN_DISCOVERY; xpt_freeze_simq(sc->sassc->sim, 1); @@ -1104,7 +1124,8 @@ mpssas_handle_reinit(struct mps_softc *s /* complete and cleanup after all outstanding commands */ mpssas_complete_all_commands(sc); - mps_printf(sc, "%s startup %u tm %u after command completion\n", + mps_dprint(sc, MPS_INIT, + "%s startup %u tm %u after command completion\n", __func__, sc->sassc->startup_refcount, sc->sassc->tm_count); /* @@ -1119,7 +1140,7 @@ mpssas_handle_reinit(struct mps_softc *s */ for (i = 0; i < sc->facts->MaxTargets; i++) { if (sc->sassc->targets[i].outstanding != 0) - mps_printf(sc, "target %u outstanding %u\n", + mps_dprint(sc, MPS_INIT, "target %u outstanding %u\n", i, sc->sassc->targets[i].outstanding); sc->sassc->targets[i].handle = 0x0; sc->sassc->targets[i].exp_dev_handle = 0x0; @@ -1127,6 +1148,7 @@ mpssas_handle_reinit(struct mps_softc *s sc->sassc->targets[i].flags = MPSSAS_TARGET_INDIAGRESET; } } + static void mpssas_tm_timeout(void *data) { @@ -1135,7 +1157,8 @@ mpssas_tm_timeout(void *data) mtx_assert(&sc->mps_mtx, MA_OWNED); - mpssas_log_command(tm, "task mgmt %p timed out\n", tm); + mpssas_log_command(tm, MPS_INFO|MPS_RECOVERY, + "task mgmt %p timed out\n", tm); mps_reinit(sc); } @@ -1158,16 +1181,18 @@ mpssas_logical_unit_reset_complete(struc * Currently there should be no way we can hit this case. It only * happens when we have a failure to allocate chain frames, and * task management commands don't have S/G lists. *** DIFF OUTPUT TRUNCATED AT 1000 LINES ***
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201307190012.r6J0Cg1r027645>