Changeset defaab2 in mainline


Ignore:
Timestamp:
2018-01-20T22:46:24Z (6 years ago)
Author:
Ondřej Hlavatý <aearsis@…>
Branches:
lfn, master, serial, ticket/834-toolchain-update, topic/msim-upgrade, topic/simplify-dev-export
Children:
217e981
Parents:
9d3536e
Message:

xhci: tune log levels

Location:
uspace
Files:
10 edited

Legend:

Unmodified
Added
Removed

  • uspace/drv/bus/usb/xhci/commands.c

    r9d3536e rdefaab2  
    339339                 * requesting thread is waiting inside the CV.
    340340                 */
    341                 usb_log_debug2("Command ring stopped.");
     341                usb_log_debug("Command ring stopped.");
    342342                fibril_condvar_broadcast(&cr->stopped_cv);
    343343                fibril_mutex_unlock(&cr->guard);

  • uspace/drv/bus/usb/xhci/debug.c

    r9d3536e rdefaab2  
    4545
    4646#define DUMP_REG_FIELD(ptr, title, size, ...) \
    47         usb_log_debug2(PX "%" PRIu##size, title, XHCI_REG_RD_FIELD(ptr, size, ##__VA_ARGS__))
     47        usb_log_debug(PX "%" PRIu##size, title, XHCI_REG_RD_FIELD(ptr, size, ##__VA_ARGS__))
    4848
    4949#define DUMP_REG_RANGE(ptr, title, size, ...) \
    50         usb_log_debug2(PX "%" PRIu##size, title, XHCI_REG_RD_RANGE(ptr, size, ##__VA_ARGS__))
     50        usb_log_debug(PX "%" PRIu##size, title, XHCI_REG_RD_RANGE(ptr, size, ##__VA_ARGS__))
    5151
    5252#define DUMP_REG_FLAG(ptr, title, size, ...) \
    53         usb_log_debug2(PX "%s", title, XHCI_REG_RD_FLAG(ptr, size, ##__VA_ARGS__) ? "true" : "false")
     53        usb_log_debug(PX "%s", title, XHCI_REG_RD_FLAG(ptr, size, ##__VA_ARGS__) ? "true" : "false")
    5454
    5555#define DUMP_REG_INNER(set, title, field, size, type, ...) \
    … …  
    6363void xhci_dump_cap_regs(const xhci_cap_regs_t *cap)
    6464{
    65         usb_log_debug2("Capabilities:");
     65        usb_log_debug("Capabilities:");
    6666
    6767        DUMP_REG(cap, XHCI_CAP_LENGTH);
    … …  
    7272        DUMP_REG(cap, XHCI_CAP_IST);
    7373        DUMP_REG(cap, XHCI_CAP_ERST_MAX);
    74         usb_log_debug2(PX "%u", "Max Scratchpad bufs", xhci_get_max_spbuf(cap));
     74        usb_log_debug(PX "%u", "Max Scratchpad bufs", xhci_get_max_spbuf(cap));
    7575        DUMP_REG(cap, XHCI_CAP_SPR);
    7676        DUMP_REG(cap, XHCI_CAP_U1EL);
    … …  
    149149void xhci_dump_state(const xhci_hc_t *hc)
    150150{
    151         usb_log_debug2("Operational registers:");
     151        usb_log_debug("Operational registers:");
    152152
    153153        DUMP_REG(hc->op_regs, XHCI_OP_RS);
    … …  
    182182        DUMP_REG(hc->rt_regs, XHCI_RT_MFINDEX);
    183183
    184         usb_log_debug2("Interrupter 0 state:");
     184        usb_log_debug("Interrupter 0 state:");
    185185        DUMP_REG(&hc->rt_regs->ir[0], XHCI_INTR_IP);
    186186        DUMP_REG(&hc->rt_regs->ir[0], XHCI_INTR_IE);
    … …  
    201201        const size_t num_ports = XHCI_REG_RD(hc->cap_regs, XHCI_CAP_MAX_PORTS);
    202202        for (size_t i = 0; i < num_ports; i++) {
    203                 usb_log_debug2("Port %zu state:", i);
     203                usb_log_debug("Port %zu state:", i);
    204204
    205205                xhci_dump_port(&hc->op_regs->portrs[i]);
    … …  
    264264void xhci_dump_trb(const xhci_trb_t *trb)
    265265{
    266         usb_log_debug2("TRB(%p): type %s, cycle %u, status 0x%#08" PRIx32 ", parameter 0x%#016" PRIx64, trb, xhci_trb_str_type(TRB_TYPE(*trb)), TRB_CYCLE(*trb), trb->status, trb->parameter);
     266        usb_log_debug("TRB(%p): type %s, cycle %u, status 0x%#08" PRIx32 ", parameter 0x%#016" PRIx64, trb, xhci_trb_str_type(TRB_TYPE(*trb)), TRB_CYCLE(*trb), trb->status, trb->parameter);
    267267}
    268268

  • uspace/drv/bus/usb/xhci/device.c

    r9d3536e rdefaab2  
    7676        if ((err = hc_enable_slot(dev)) != EOK)
    7777                return err;
    78         usb_log_debug2("Obtained slot ID: %u.", dev->slot_id);
     78        usb_log_debug("Obtained slot ID: %u.", dev->slot_id);
    7979
    8080        /* Create and configure control endpoint. */
    … …  
    8787        dev->base.endpoints[0] = ep0_base;
    8888
    89         usb_log_debug2("Looking up new device initial speed: %i", dev->base.speed);
     89        usb_log_debug("Looking up new device initial MPS: %s", usb_str_speed(dev->base.speed));
    9090        ep0_base->max_packet_size = hc_get_ep0_initial_mps(dev->base.speed);
    9191
    … …  
    160160        }
    161161
    162         usb_log_debug2("Device(%u): recognised USB hub with %u ports", dev->base.address, dev->num_ports);
     162        usb_log_debug("Device(%u): recognised USB hub with %u ports", dev->base.address, dev->num_ports);
    163163        return EOK;
    164164}

  • uspace/drv/bus/usb/xhci/endpoint.c

    r9d3536e rdefaab2  
    279279{
    280280        /* Can't use XHCI_EP_FMT because the endpoint may not have device. */
    281         usb_log_debug2("Allocating main transfer ring for endpoint " XHCI_EP_FMT, XHCI_EP_ARGS(*xhci_ep));
     281        usb_log_debug("Allocating main transfer ring for endpoint " XHCI_EP_FMT, XHCI_EP_ARGS(*xhci_ep));
    282282
    283283        xhci_ep->primary_stream_data_array = NULL;
    … …  
    307307                xhci_stream_free_ds(xhci_ep);
    308308        } else {
    309                 usb_log_debug2("Freeing main transfer ring of endpoint " XHCI_EP_FMT, XHCI_EP_ARGS(*xhci_ep));
     309                usb_log_debug("Freeing main transfer ring of endpoint " XHCI_EP_FMT, XHCI_EP_ARGS(*xhci_ep));
    310310                xhci_trb_ring_fini(&xhci_ep->ring);
    311311        }

  • uspace/drv/bus/usb/xhci/hc.c

    r9d3536e rdefaab2  
    128128                                }
    129129
    130                                 usb_log_debug2("Implied speed of USB %u.0 set up.", major);
     130                                usb_log_debug("Implied speed of USB %u.0 set up.", major);
    131131                        } else {
    132132                                for (unsigned i = 0; i < psic; i++) {
    … …  
    157157                                           && default_psiv_to_port_speed[psiv].tx_bps == bps) {
    158158                                                speeds[psiv] = default_psiv_to_port_speed[psiv];
    159                                                 usb_log_debug2("Assumed default %s speed of USB %u.", usb_str_speed(speeds[psiv].usb_speed), major);
     159                                                usb_log_debug("Assumed default %s speed of USB %u.", usb_str_speed(speeds[psiv].usb_speed), major);
    160160                                                continue;
    161161                                        }
    … …  
    171171                                        if (sim == XHCI_PSI_PLT_SYMM || sim == XHCI_PSI_PLT_TX) {
    172172                                                speeds[psiv].tx_bps = bps;
    173                                                 usb_log_debug2("Speed %u set up for bps %" PRIu64 " / %" PRIu64 ".", psiv, speeds[psiv].rx_bps, speeds[psiv].tx_bps);
     173                                                usb_log_debug("Speed %u set up for bps %" PRIu64 " / %" PRIu64 ".", psiv, speeds[psiv].rx_bps, speeds[psiv].tx_bps);
    174174                                        }
    175175                                }
    … …  
    214214                hc->xecp = (xhci_extcap_t *) (base + xec_offset);
    215215
    216         usb_log_debug2("Initialized MMIO reg areas:");
    217         usb_log_debug2("\tCapability regs: %p", hc->cap_regs);
    218         usb_log_debug2("\tOperational regs: %p", hc->op_regs);
    219         usb_log_debug2("\tRuntime regs: %p", hc->rt_regs);
    220         usb_log_debug2("\tDoorbell array base: %p", hc->db_arry);
     216        usb_log_debug("Initialized MMIO reg areas:");
     217        usb_log_debug("\tCapability regs: %p", hc->cap_regs);
     218        usb_log_debug("\tOperational regs: %p", hc->op_regs);
     219        usb_log_debug("\tRuntime regs: %p", hc->rt_regs);
     220        usb_log_debug("\tDoorbell array base: %p", hc->db_arry);
    221221
    222222        xhci_dump_cap_regs(hc->cap_regs);
    … …  
    419419                return ETIMEOUT;
    420420
    421         usb_log_debug2("LEGSUP: bios: %x, os: %x", hc->legsup->sem_bios, hc->legsup->sem_os);
     421        usb_log_debug("LEGSUP: bios: %x, os: %x", hc->legsup->sem_bios, hc->legsup->sem_os);
    422422        XHCI_REG_SET(hc->legsup, XHCI_LEGSUP_SEM_OS, 1);
    423423        for (int i = 0; i <= (XHCI_LEGSUP_BIOS_TIMEOUT_US / XHCI_LEGSUP_POLLING_DELAY_1MS); i++) {
    424                 usb_log_debug2("LEGSUP: elapsed: %i ms, bios: %x, os: %x", i,
     424                usb_log_debug("LEGSUP: elapsed: %i ms, bios: %x, os: %x", i,
    425425                        XHCI_REG_RD(hc->legsup, XHCI_LEGSUP_SEM_BIOS),
    426426                        XHCI_REG_RD(hc->legsup, XHCI_LEGSUP_SEM_OS));
    … …  
    526526        }
    527527
    528         usb_log_debug2("Polled status: %x", *status);
     528        usb_log_debug("Polled status: %x", *status);
    529529        return EOK;
    530530}
    … …  
    534534        struct timeval tv;
    535535        getuptime(&tv);
    536         usb_log_debug2("Microframe index wrapped (@%lu.%li, %"PRIu64" total).", tv.tv_sec, tv.tv_usec, hc->wrap_count);
     536        usb_log_debug("Microframe index wrapped (@%lu.%li, %"PRIu64" total).", tv.tv_sec, tv.tv_usec, hc->wrap_count);
    537537        hc->wrap_time = ((uint64_t) tv.tv_sec) * 1000000 + ((uint64_t) tv.tv_usec);
    538538        ++hc->wrap_count;
    … …  
    856856        xhci_device_ctx_t *device_ctx = dev->dev_ctx.virt;
    857857        dev->base.address = XHCI_SLOT_DEVICE_ADDRESS(*XHCI_GET_SLOT_CTX(device_ctx, hc));
    858         usb_log_debug2("Obtained USB address: %d.", dev->base.address);
     858        usb_log_debug("Obtained USB address: %d.", dev->base.address);
    859859
    860860        return EOK;

  • uspace/drv/bus/usb/xhci/isoch.c

    r9d3536e rdefaab2  
    6565        isoch->buffer_count = max(2, isoch->buffer_count);
    6666
    67         usb_log_debug2("[isoch] isoch setup with %zu buffers", isoch->buffer_count);
     67        usb_log_debug("[isoch] isoch setup with %zu buffers", isoch->buffer_count);
    6868}
    6969
    … …  
    311311                case WINDOW_TOO_SOON: {
    312312                        const suseconds_t delay = wd.offset * 125;
    313                         usb_log_debug2("[isoch] delaying feeding buffer %lu for %ldus",
     313                        usb_log_debug("[isoch] delaying feeding buffer %lu for %ldus",
    314314                                it - isoch->transfers, delay);
    315315                        fibril_timer_set_locked(isoch->feeding_timer, delay,
    … …  
    319319
    320320                case WINDOW_INSIDE:
    321                         usb_log_debug2("[isoch] feeding buffer %lu at 0x%llx",
     321                        usb_log_debug("[isoch] feeding buffer %lu at 0x%llx",
    322322                            it - isoch->transfers, it->mfindex);
    323323                        it->error = schedule_isochronous_trb(ep, it);
    … …  
    334334                case WINDOW_TOO_LATE:
    335335                        /* Missed the opportunity to schedule. Just mark this transfer as skipped. */
    336                         usb_log_debug2("[isoch] missed feeding buffer %lu at 0x%llx by %llu uframes",
     336                        usb_log_debug("[isoch] missed feeding buffer %lu at 0x%llx by %llu uframes",
    337337                            it - isoch->transfers, it->mfindex, wd.offset);
    338338                        it->state = ISOCH_COMPLETE;
    … …  
    397397                        /* Not allowed to feed yet. Defer to later. */
    398398                        const suseconds_t delay = wd.offset * 125;
    399                         usb_log_debug2("[isoch] delaying feeding buffer %lu for %ldus",
     399                        usb_log_debug("[isoch] delaying feeding buffer %lu for %ldus",
    400400                            it - isoch->transfers, delay);
    401401                        fibril_timer_set_locked(isoch->feeding_timer, delay,
    … …  
    405405
    406406                case WINDOW_TOO_LATE:
    407                         usb_log_debug2("[isoch] missed feeding buffer %lu at 0x%llx by %llu uframes",
     407                        usb_log_debug("[isoch] missed feeding buffer %lu at 0x%llx by %llu uframes",
    408408                            it - isoch->transfers, it->mfindex, wd.offset);
    409409                        /* Missed the opportunity to schedule. Schedule ASAP. */
    … …  
    418418                        isoch->last_mf = it->mfindex;
    419419
    420                         usb_log_debug2("[isoch] feeding buffer %lu at 0x%llx",
     420                        usb_log_debug("[isoch] feeding buffer %lu at 0x%llx",
    421421                            it - isoch->transfers, it->mfindex);
    422422
    … …  
    502502        calc_next_mfindex(ep, it);
    503503        isoch->last_mf = it->mfindex;
    504         usb_log_debug2("[isoch] buffer %zu will be on schedule at 0x%llx", it - isoch->transfers, it->mfindex);
     504        usb_log_debug("[isoch] buffer %zu will be on schedule at 0x%llx", it - isoch->transfers, it->mfindex);
    505505
    506506        /* Prepare the transfer. */
    … …  
    543543                isoch_feed_in(ep);
    544544
    545                 usb_log_debug2("[isoch] waiting for buffer %zu to be completed", it - isoch->transfers);
     545                usb_log_debug("[isoch] waiting for buffer %zu to be completed", it - isoch->transfers);
    546546                fibril_condvar_wait(&isoch->avail, &isoch->guard);
    547547
    … …  
    615615
    616616                if (it->state == ISOCH_FED && it->interrupt_trb_phys == trb->parameter) {
    617                         usb_log_debug2("[isoch] buffer %zu completed", it - isoch->transfers);
     617                        usb_log_debug("[isoch] buffer %zu completed", it - isoch->transfers);
    618618                        it->state = ISOCH_COMPLETE;
    619619                        it->size -= TRB_TRANSFER_LENGTH(*trb);

  • uspace/drv/bus/usb/xhci/scratchpad.c

    r9d3536e rdefaab2  
    8080        hc->dcbaa[0] = host2xhci(64, hc->scratchpad_array.phys);
    8181
    82         usb_log_debug2("Allocated %d scratchpad buffers.", num_bufs);
     82        usb_log_debug("Allocated %d scratchpad buffers.", num_bufs);
    8383
    8484        return EOK;

  • uspace/drv/bus/usb/xhci/streams.c

    r9d3536e rdefaab2  
    8282static int initialize_primary_structures(xhci_endpoint_t *xhci_ep, unsigned count)
    8383{
    84         usb_log_debug2("Allocating primary stream context array of size %u for endpoint " XHCI_EP_FMT,
     84        usb_log_debug("Allocating primary stream context array of size %u for endpoint " XHCI_EP_FMT,
    8585                count, XHCI_EP_ARGS(*xhci_ep));
    8686
    … …  
    106106static void clear_primary_structures(xhci_endpoint_t *xhci_ep)
    107107{
    108         usb_log_debug2("Deallocating primary stream structures for endpoint " XHCI_EP_FMT, XHCI_EP_ARGS(*xhci_ep));
     108        usb_log_debug("Deallocating primary stream structures for endpoint " XHCI_EP_FMT, XHCI_EP_ARGS(*xhci_ep));
    109109
    110110        dma_buffer_free(&xhci_ep->primary_stream_ctx_dma);
    … …  
    133133void xhci_stream_free_ds(xhci_endpoint_t *xhci_ep)
    134134{
    135         usb_log_debug2("Freeing stream rings and context arrays of endpoint " XHCI_EP_FMT, XHCI_EP_ARGS(*xhci_ep));
     135        usb_log_debug("Freeing stream rings and context arrays of endpoint " XHCI_EP_FMT, XHCI_EP_ARGS(*xhci_ep));
    136136
    137137        for (size_t index = 0; index < xhci_ep->primary_stream_data_size; ++index) {

  • uspace/drv/bus/usb/xhci/trb_ring.c

    r9d3536e rdefaab2  
    8585        memset(*segment, 0, PAGE_SIZE);
    8686        (*segment)->phys = dbuf.phys;
    87         usb_log_debug2("Allocated new ring segment.");
     87        usb_log_debug("Allocated new ring segment.");
    8888        return EOK;
    8989}
    … …  
    247247                        if (TRB_LINK_TC(*ring->enqueue_trb)) {
    248248                                ring->pcs = !ring->pcs;
    249                                 usb_log_debug2("TRB ring(%p): PCS toggled", ring);
     249                                usb_log_debug("TRB ring(%p): PCS toggled", ring);
    250250                        }
    251251

  • uspace/lib/usbhost/src/endpoint.c

    r9d3536e rdefaab2  
    203203    usbhc_iface_transfer_callback_t on_complete, void *arg, const char *name)
    204204{
    205         usb_log_debug2("%s %d:%d %zu(%zu).",
    206             name, target.address, target.endpoint, size, ep->max_packet_size);
     205        if (!ep)
     206                return EBADMEM;
     207
     208        if (ep->transfer_type == USB_TRANSFER_CONTROL) {
     209                usb_log_debug("%s %d:%d %zu/%zuB, setup %#016" PRIx64, name,
     210                    target.address, target.endpoint, size, ep->max_packet_size,
     211                    setup_data);
     212        } else {
     213                usb_log_debug("%s %d:%d %zu/%zuB", name, target.address,
     214                    target.endpoint, size, ep->max_packet_size);
     215        }
    207216
    208217        device_t * const device = ep->device;
Note: See TracChangeset for help on using the changeset viewer.