Ticket #12634: 0001-ahci-Disable-tracing-make-tracing-more-chatty.patch

File 0001-ahci-Disable-tracing-make-tracing-more-chatty.patch, 11.3 KB (added by kallisti5, 8 years ago)

Patch v1, to be tested

  • src/add-ons/kernel/busses/scsi/ahci/ahci_port.cpp 

    From 8f2cf3fcfbceb4e3f5f66dcb7c2a178c91092529 Mon Sep 17 00:00:00 2001
From: Alexander von Gluck IV <kallisti5@unixzen.com>
Date: Thu, 7 Jul 2016 18:16:14 -0500
Subject: [PATCH] ahci: Disable tracing, make tracing more chatty

* AHCI has been shipping with tracing enabled which
  account for most of the chatty messages in #12634
* Instead of covering up a bunch of AHCI trace messages,
  lets disable tracing by default and make tracing more
  chatty overall.
* Tracing now should give you a ton of insight into
  whats going on to an obnoxious degree.  Disable tracing
  and things are silent (minus the nice link port speed)
---
 src/add-ons/kernel/busses/scsi/ahci/ahci_port.cpp | 106 +++++++++++-----------
 1 file changed, 52 insertions(+), 54 deletions(-)

diff --git a/src/add-ons/kernel/busses/scsi/ahci/ahci_port.cpp b/src/add-ons/kernel/busses/scsi/ahci/ahci_port.cpp
index dbe64cc..28201e2 100644
    a b  
    3030#include "util.h"
    3131
    3232
    33 #define TRACE_AHCI
     33//#define TRACE_AHCI
    3434#ifdef TRACE_AHCI
    3535#   define TRACE(a...) dprintf("ahci: " a)
    3636#else
    … … AHCIPort::Probe()  
    284284        return B_ERROR;
    285285    }
    286286
    287     switch (fRegs->ssts & HBA_PORT_SPD_MASK) {
    288         case 0x10:
    289             TRACE("%s: port %d link speed 1.5Gb/s\n", __func__, fIndex);
    290             break;
    291         case 0x20:
    292             TRACE("%s: port %d link speed 3.0Gb/s\n", __func__, fIndex);
    293             break;
    294         case 0x30:
    295             TRACE("%s: port %d link speed 6.0Gb/s\n", __func__, fIndex);
    296             break;
    297         default:
    298             TRACE("%s: port %d link speed unrestricted\n", __func__, fIndex);
    299             break;
     287    if (!fTestUnitReadyActive) {
     288        switch (fRegs->ssts & HBA_PORT_SPD_MASK) {
     289            case 0x10:
     290                ERROR("%s: port %d link speed 1.5Gb/s\n", __func__, fIndex);
     291                break;
     292            case 0x20:
     293                ERROR("%s: port %d link speed 3.0Gb/s\n", __func__, fIndex);
     294                break;
     295            case 0x30:
     296                ERROR("%s: port %d link speed 6.0Gb/s\n", __func__, fIndex);
     297                break;
     298            default:
     299                ERROR("%s: port %d link speed unrestricted\n", __func__, fIndex);
     300                break;
     301        }
    300302    }
    301303
    302304    wait_until_clear(&fRegs->tfd, ATA_STATUS_BUSY, 31000000);
    … … AHCIPort::Probe()  
    310312        fRegs->cmd &= ~PORT_CMD_ATAPI;
    311313    FlushPostedWrites();
    312314
    313     if (!fTestUnitReadyActive) {
    314         TRACE("device signature 0x%08" B_PRIx32 " (%s)\n", fRegs->sig,
    315             fRegs->sig == SATA_SIG_ATAPI ? "ATAPI" : fRegs->sig == SATA_SIG_ATA
    316                 ? "ATA" : "unknown");
    317     }
     315    TRACE("device signature 0x%08" B_PRIx32 " (%s)\n", fRegs->sig,
     316        fRegs->sig == SATA_SIG_ATAPI ? "ATAPI" : fRegs->sig == SATA_SIG_ATA
     317            ? "ATA" : "unknown");
    318318
    319319    return B_OK;
    320320}
    … … AHCIPort::InterruptErrorHandler(uint32 is)  
    383383{
    384384    uint32 ci = fRegs->ci;
    385385
    386     if (!fTestUnitReadyActive) {
    387         TRACE("AHCIPort::InterruptErrorHandler port %d, fCommandsActive 0x%08"
    388             B_PRIx32 ", is 0x%08" B_PRIx32 ", ci 0x%08" B_PRIx32 "\n", fIndex,
    389             fCommandsActive, is, ci);
    390         TRACE("ssts 0x%08" B_PRIx32 "\n", fRegs->ssts);
    391         TRACE("sctl 0x%08" B_PRIx32 "\n", fRegs->sctl);
    392         TRACE("serr 0x%08" B_PRIx32 "\n", fRegs->serr);
    393         TRACE("sact 0x%08" B_PRIx32 "\n", fRegs->sact);
    394     }
     386    TRACE("AHCIPort::InterruptErrorHandler port %d, fCommandsActive 0x%08"
     387        B_PRIx32 ", is 0x%08" B_PRIx32 ", ci 0x%08" B_PRIx32 "\n", fIndex,
     388        fCommandsActive, is, ci);
     389    TRACE("ssts 0x%08" B_PRIx32 "\n", fRegs->ssts);
     390    TRACE("sctl 0x%08" B_PRIx32 "\n", fRegs->sctl);
     391    TRACE("serr 0x%08" B_PRIx32 "\n", fRegs->serr);
     392    TRACE("sact 0x%08" B_PRIx32 "\n", fRegs->sact);
    395393
    396394    // read and clear SError
    397395    _ClearErrorRegister();
    398396
    399397    if (is & PORT_INT_TFE) {
    400         if (!fTestUnitReadyActive)
    401             TRACE("Task File Error\n");
     398        TRACE("Task File Error\n");
    402399
    403400        fPortReset = true;
    404401        fError = true;
    405402    }
    406403    if (is & PORT_INT_HBF) {
    407         TRACE("Host Bus Fatal Error\n");
     404        ERROR("Host Bus Fatal Error\n");
    408405        fPortReset = true;
    409406        fError = true;
    410407    }
    411408    if (is & PORT_INT_HBD) {
    412         TRACE("Host Bus Data Error\n");
     409        ERROR("Host Bus Data Error\n");
    413410        fPortReset = true;
    414411        fError = true;
    415412    }
    416413    if (is & PORT_INT_IF) {
    417         TRACE("Interface Fatal Error\n");
     414        ERROR("Interface Fatal Error\n");
    418415        fPortReset = true;
    419416        fError = true;
    420417    }
    … … AHCIPort::FillPrdTable(volatile prd* prdTable, int* prdCount, int prdMax,  
    468465    status_t status = get_memory_map_etc(B_CURRENT_TEAM, data, dataSize,
    469466        entries, &entriesUsed);
    470467    if (status != B_OK) {
    471         TRACE("%s: get_memory_map() failed: %s\n", __func__, strerror(status));
     468        ERROR("%s: get_memory_map() failed: %s\n", __func__, strerror(status));
    472469        return B_ERROR;
    473470    }
    474471
    … … AHCIPort::FillPrdTable(volatile prd* prdTable, int* prdCount, int prdMax,  
    489486        FLOW("FillPrdTable: sg-entry addr %#" B_PRIxPHYSADDR ", size %lu\n",
    490487            address, size);
    491488        if (address & 1) {
    492             TRACE("AHCIPort::FillPrdTable: data alignment error\n");
     489            ERROR("AHCIPort::FillPrdTable: data alignment error\n");
    493490            return B_ERROR;
    494491        }
    495492        dataSize -= size;
    496493        while (size > 0) {
    497494            size_t bytes = min_c(size, PRD_MAX_DATA_LENGTH);
    498495            if (*prdCount == prdMax) {
    499                 TRACE("AHCIPort::FillPrdTable: prd table exhausted\n");
     496                ERROR("AHCIPort::FillPrdTable: prd table exhausted\n");
    500497                return B_ERROR;
    501498            }
    502499            FLOW("FillPrdTable: prd-entry %u, addr %p, size %lu\n",
    … … AHCIPort::FillPrdTable(volatile prd* prdTable, int* prdCount, int prdMax,  
    515512        sgCount--;
    516513    }
    517514    if (*prdCount == 0) {
    518         TRACE("%s: count is 0\n", __func__);
     515        ERROR("%s: count is 0\n", __func__);
    519516        return B_ERROR;
    520517    }
    521518    if (dataSize > 0) {
    522         TRACE("AHCIPort::FillPrdTable: sg table %ld bytes too small\n",
     519        ERROR("AHCIPort::FillPrdTable: sg table %ld bytes too small\n",
    523520            dataSize);
    524521        return B_ERROR;
    525522    }
    … … AHCIPort::ScsiSynchronizeCache(scsi_ccb* request)  
    811808
    812809    sata_request* sreq = new(std::nothrow) sata_request(request);
    813810    if (sreq == NULL) {
    814         TRACE("out of memory when allocating sync request\n");
     811        ERROR("out of memory when allocating sync request\n");
    815812        request->subsys_status = SCSI_REQ_ABORTED;
    816813        gSCSI->finished(request, 1);
    817814        return;
    … … for (uint32 i = 0; i < scsiRangeCount; i++) {  
    981978        uint32 lbaRangesSize = lbaRangeCount * sizeof(uint64);
    982979        uint64* lbaRanges = (uint64*)malloc(lbaRangesSize);
    983980        if (lbaRanges == NULL) {
    984             TRACE("out of memory when allocating %" B_PRIu32 " unmap ranges\n",
     981            ERROR("out of memory when allocating %" B_PRIu32 " unmap ranges\n",
    985982                lbaRangeCount);
    986983            request->subsys_status = SCSI_REQ_ABORTED;
    987984            gSCSI->finished(request, 1);
    … … for (uint32 i = 0; i < lbaRangeCount; i++) {  
    10371034        sreq.WaitForCompletion();
    10381035
    10391036        if ((sreq.CompletionStatus() & ATA_STATUS_ERROR) != 0) {
    1040             TRACE("trim failed (%" B_PRIu32 " ranges)!\n", lbaRangeCount);
     1037            ERROR("trim failed (%" B_PRIu32 " ranges)!\n", lbaRangeCount);
    10411038            request->subsys_status = SCSI_REQ_CMP_ERR;
    10421039        } else
    10431040            request->subsys_status = SCSI_REQ_CMP;
    … … AHCIPort::ExecuteSataRequest(sata_request* request, bool isWrite)  
    10931090
    10941091    if (wait_until_clear(&fRegs->tfd, ATA_STATUS_BUSY | ATA_STATUS_DATA_REQUEST,
    10951092            1000000) < B_OK) {
    1096         TRACE("ExecuteAtaRequest port %d: device is busy\n", fIndex);
     1093        ERROR("ExecuteAtaRequest port %d: device is busy\n", fIndex);
    10971094        PortReset();
    10981095        FinishTransfer();
    10991096        request->Abort();
    … … AHCIPort::ExecuteSataRequest(sata_request* request, bool isWrite)  
    11401137    FinishTransfer();
    11411138
    11421139    if (status == B_TIMED_OUT) {
    1143         TRACE("ExecuteAtaRequest port %d: device timeout\n", fIndex);
     1140        ERROR("ExecuteAtaRequest port %d: device timeout\n", fIndex);
    11441141        request->Abort();
    11451142        return;
    11461143    }
    … … AHCIPort::ScsiExecuteRequest(scsi_ccb* request)  
    11751172
    11761173        sata_request* sreq = new(std::nothrow) sata_request(request);
    11771174        if (sreq == NULL) {
    1178             TRACE("out of memory when allocating atapi request\n");
     1175            ERROR("out of memory when allocating atapi request\n");
    11791176            request->subsys_status = SCSI_REQ_ABORTED;
    11801177            gSCSI->finished(request, 1);
    11811178            return;
    … … AHCIPort::ScsiExecuteRequest(scsi_ccb* request)  
    12461243            if (length) {
    12471244                ScsiReadWrite(request, position, length, isWrite);
    12481245            } else {
    1249                 TRACE("AHCIPort::ScsiExecuteRequest error: transfer without "
     1246                ERROR("AHCIPort::ScsiExecuteRequest error: transfer without "
    12501247                    "data!\n");
    12511248                request->subsys_status = SCSI_REQ_INVALID;
    12521249                gSCSI->finished(request, 1);
    … … AHCIPort::ScsiExecuteRequest(scsi_ccb* request)  
    12631260            if (length) {
    12641261                ScsiReadWrite(request, position, length, isWrite);
    12651262            } else {
    1266                 TRACE("AHCIPort::ScsiExecuteRequest error: transfer without "
     1263                ERROR("AHCIPort::ScsiExecuteRequest error: transfer without "
    12671264                    "data!\n");
    12681265                request->subsys_status = SCSI_REQ_INVALID;
    12691266                gSCSI->finished(request, 1);
    … … AHCIPort::ScsiExecuteRequest(scsi_ccb* request)  
    12801277            if (length) {
    12811278                ScsiReadWrite(request, position, length, isWrite);
    12821279            } else {
    1283                 TRACE("AHCIPort::ScsiExecuteRequest error: transfer without "
     1280                ERROR("AHCIPort::ScsiExecuteRequest error: transfer without "
    12841281                    "data!\n");
    12851282                request->subsys_status = SCSI_REQ_INVALID;
    12861283                gSCSI->finished(request, 1);
    … … AHCIPort::ScsiExecuteRequest(scsi_ccb* request)  
    12921289            const scsi_cmd_unmap* cmd = (const scsi_cmd_unmap*)request->cdb;
    12931290
    12941291            if (!fTrimSupported) {
    1295                 TRACE("%s port %d: unsupported request opcode 0x%02x\n",
     1292                ERROR("%s port %d: unsupported request opcode 0x%02x\n",
    12961293                    __func__, fIndex, request->cdb[0]);
    12971294                request->subsys_status = SCSI_REQ_ABORTED;
    12981295                gSCSI->finished(request, 1);
    … … AHCIPort::ScsiExecuteRequest(scsi_ccb* request)  
    13051302                || B_BENDIAN_TO_HOST_INT16(cmd->length) != request->data_length
    13061303                || B_BENDIAN_TO_HOST_INT16(unmapBlocks->data_length)
    13071304                    != request->data_length - 1) {
    1308                 TRACE("%s port %d: invalid unmap parameter data length\n",
     1305                ERROR("%s port %d: invalid unmap parameter data length\n",
    13091306                    __func__, fIndex);
    13101307                request->subsys_status = SCSI_REQ_ABORTED;
    13111308                gSCSI->finished(request, 1);
    … … AHCIPort::ScsiExecuteRequest(scsi_ccb* request)  
    13151312            break;
    13161313        }
    13171314        default:
    1318             TRACE("AHCIPort::ScsiExecuteRequest port %d unsupported request "
     1315            ERROR("AHCIPort::ScsiExecuteRequest port %d unsupported request "
    13191316                "opcode 0x%02x\n", fIndex, request->cdb[0]);
    13201317            request->subsys_status = SCSI_REQ_ABORTED;
    13211318            gSCSI->finished(request, 1);
    … … AHCIPort::Enable()  
    13621359{
    13631360    // Spec v1.3.1, §10.3.1 Start (PxCMD.ST)
    13641361    TRACE("%s: port %d\n", __func__, fIndex);
     1362
    13651363    if ((fRegs->cmd & PORT_CMD_ST) != 0) {
    1366         TRACE("%s: Starting port already running!\n", __func__);
     1364        ERROR("%s: Starting port already running!\n", __func__);
    13671365        return false;
    13681366    }
    13691367
    13701368    if ((fRegs->cmd & PORT_CMD_FRE) == 0) {
    1371         TRACE("%s: Unable to start port without FRE enabled!\n", __func__);
     1369        ERROR("%s: Unable to start port without FRE enabled!\n", __func__);
    13721370        return false;
    13731371    }
    13741372
    13751373    // Clear DMA engine and wait for completion
    13761374    if (wait_until_clear(&fRegs->cmd, PORT_CMD_CR, 500000) < B_OK) {
    1377         TRACE("%s: port %d error DMA engine still running\n", __func__,
     1375        ERROR("%s: port %d error DMA engine still running\n", __func__,
    13781376            fIndex);
    13791377        return false;
    13801378    }
    … … AHCIPort::Disable()  
    14031401    // Spec v1.3.1, §10.4.2 Port Reset - assume hung after 500 mil.
    14041402    // Clear DMA engine and wait for completion
    14051403    if (wait_until_clear(&fRegs->cmd, PORT_CMD_CR, 500000) < B_OK) {
    1406         TRACE("%s: port %d error DMA engine still running\n", __func__,
     1404        ERROR("%s: port %d error DMA engine still running\n", __func__,
    14071405            fIndex);
    14081406        return false;
    14091407    }