From: Alex Rousskov Date: Fri, 4 Apr 2014 16:10:40 +0000 (-0600) Subject: Report IpcIo file name with errors and warnings X-Git-Tag: SQUID_3_5_0_1~170^2~12 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=82ed74dc176195b515e07187351531151ffb9e8d;p=thirdparty%2Fsquid.git Report IpcIo file name with errors and warnings to inform admin which cache_dir needs troubleshooting or tuning. Some level-0/1 messages did not mention disker ID or file name at all while others relied on disker process ID which is too low-level information from most admins point of view. Also improved error and warning messages consistency. --- diff --git a/src/DiskIO/IpcIo/IpcIoFile.cc b/src/DiskIO/IpcIo/IpcIoFile.cc index 6b7a67500a..87902ee893 100644 --- a/src/DiskIO/IpcIo/IpcIoFile.cc +++ b/src/DiskIO/IpcIo/IpcIoFile.cc @@ -140,7 +140,8 @@ IpcIoFile::openCompleted(const Ipc::StrandSearchResponse *const response) Must(diskId < 0); // we do not know our disker yet if (!response) { - debugs(79, DBG_IMPORTANT, HERE << "error: timeout"); + debugs(79, DBG_IMPORTANT, "ERROR: " << dbName << " communication " << + "channel establishment timeout"); error_ = true; } else { diskId = response->strand.kidId; @@ -150,7 +151,8 @@ IpcIoFile::openCompleted(const Ipc::StrandSearchResponse *const response) Must(inserted); } else { error_ = true; - debugs(79, DBG_IMPORTANT, HERE << "error: no disker claimed " << dbName); + debugs(79, DBG_IMPORTANT, "ERROR: no disker claimed " << + "responsibility for " << dbName); } } @@ -227,10 +229,12 @@ IpcIoFile::readCompleted(ReadRequest *readRequest, ioError = true; // I/O timeout does not warrant setting error_? } else { if (response->xerrno) { - debugs(79, DBG_IMPORTANT, HERE << "error: " << xstrerr(response->xerrno)); + debugs(79, DBG_IMPORTANT, "ERROR: " << dbName << " read: " << + xstrerr(response->xerrno)); ioError = error_ = true; } else if (!response->page) { - debugs(79, DBG_IMPORTANT, HERE << "error: run out of shared memory pages"); + debugs(79, DBG_IMPORTANT, "ERROR: " << dbName << " read ran " << + "out of shared memory pages"); ioError = true; } else { const char *const buf = Ipc::Mem::PagePointer(response->page); @@ -358,14 +362,15 @@ IpcIoFile::push(IpcIoPendingRequest *const pending) Notify(diskId); // must notify disker trackPendingRequest(ipcIo.requestId, pending); } catch (const Queue::Full &) { - debugs(47, DBG_IMPORTANT, "Worker I/O push queue overflow: " << + debugs(47, DBG_IMPORTANT, "ERROR: worker I/O push queue for " << + dbName << " overflow: " << SipcIo(KidIdentifier, ipcIo, diskId)); // TODO: report queue len // TODO: grow queue size pending->completeIo(NULL); delete pending; } catch (const TextException &e) { - debugs(47, DBG_IMPORTANT, HERE << e.what()); + debugs(47, DBG_IMPORTANT, "ERROR: " << dbName << " exception: " << e.what()); pending->completeIo(NULL); delete pending; } @@ -523,15 +528,15 @@ IpcIoFile::checkTimeouts() if (timeoutsBefore > timeoutsNow) { // some requests were rescued // notification message lost or significantly delayed? - debugs(47, DBG_IMPORTANT, "WARNING: communication with disker " << - "may be too slow or disrupted for about " << + debugs(47, DBG_IMPORTANT, "WARNING: communication with " << dbName << + " may be too slow or disrupted for about " << Timeout << "s; rescued " << (timeoutsBefore - timeoutsNow) << " out of " << timeoutsBefore << " I/Os"); } if (timeoutsNow) { debugs(47, DBG_IMPORTANT, "WARNING: abandoning " << - timeoutsNow << " I/Os after at least " << + timeoutsNow << ' ' << dbName << " I/Os after at least " << Timeout << "s timeout"); } @@ -631,6 +636,7 @@ IpcIoPendingRequest::completeIo(IpcIoMsg *const response) /* XXX: disker code that should probably be moved elsewhere */ +static String DbName; ///< full db file name static int TheFile = -1; ///< db file descriptor static void @@ -682,8 +688,8 @@ diskerWriteAttempts(IpcIoMsg &ipcIo) if (result < 0) { ipcIo.xerrno = errno; assert(ipcIo.xerrno); - debugs(47, DBG_IMPORTANT, "disker" << KidIdentifier << - " error writing " << toWrite << '/' << ipcIo.len << + debugs(47, DBG_IMPORTANT, "ERROR: " << DbName << " failure" << + " writing " << toWrite << '/' << ipcIo.len << " at " << ipcIo.offset << '+' << wroteSoFar << " on " << attempts << " try: " << xstrerr(ipcIo.xerrno)); ipcIo.len = wroteSoFar; @@ -712,8 +718,8 @@ diskerWriteAttempts(IpcIoMsg &ipcIo) toWrite -= wroteNow; } - debugs(47, DBG_IMPORTANT, "disker" << KidIdentifier << - " exhausted all " << attemptLimit << " attempts while writing " << + debugs(47, DBG_IMPORTANT, "ERROR: " << DbName << " exhausted all " << + attemptLimit << " attempts while writing " << toWrite << '/' << ipcIo.len << " at " << ipcIo.offset << '+' << wroteSoFar); return; // not a fatal I/O error, unless the caller treats it as such @@ -776,9 +782,9 @@ IpcIoFile::WaitBeforePop() const int64_t toSpend = balance - maxImbalance/2; if (toSpend/1e3 > Timeout) - debugs(47, DBG_IMPORTANT, "WARNING: Rock disker delays I/O " << - "requests for " << (toSpend/1e3) << " seconds to obey " << - ioRate << "/sec rate limit"); + debugs(47, DBG_IMPORTANT, "WARNING: " << DbName << " delays " << + "I/O requests for " << (toSpend/1e3) << " seconds " << + "to obey " << ioRate << "/sec rate limit"); debugs(47, 3, HERE << "rate limiting by " << toSpend << " ms to get" << (1e3*maxRate) << "/sec rate"); @@ -843,7 +849,7 @@ void IpcIoFile::DiskerHandleRequest(const int workerId, IpcIoMsg &ipcIo) { if (ipcIo.command != IpcIo::cmdRead && ipcIo.command != IpcIo::cmdWrite) { - debugs(0, DBG_CRITICAL, HERE << "disker" << KidIdentifier << + debugs(0, DBG_CRITICAL, "ERROR: " << DbName << " should not receive " << ipcIo.command << " ipcIo" << workerId << '.' << ipcIo.requestId); return; @@ -869,7 +875,8 @@ IpcIoFile::DiskerHandleRequest(const int workerId, IpcIoMsg &ipcIo) // before push()ing and because if disker pops N requests at a time, // we should make sure the worker pop() queue length is the worker // push queue length plus N+1. XXX: implement the N+1 difference. - debugs(47, DBG_IMPORTANT, "BUG: Worker I/O pop queue overflow: " << + debugs(47, DBG_IMPORTANT, "BUG: Worker I/O pop queue for " << + DbName << " overflow: " << SipcIo(workerId, ipcIo, KidIdentifier)); // TODO: report queue len // the I/O request we could not push will timeout @@ -881,17 +888,18 @@ DiskerOpen(const String &path, int flags, mode_t mode) { assert(TheFile < 0); - TheFile = file_open(path.termedBuf(), flags); + DbName = path; + TheFile = file_open(DbName.termedBuf(), flags); if (TheFile < 0) { const int xerrno = errno; - debugs(47, DBG_CRITICAL, HERE << "rock db error opening " << path << ": " << + debugs(47, DBG_CRITICAL, "ERROR: cannot open " << DbName << ": " << xstrerr(xerrno)); return false; } ++store_open_disk_fd; - debugs(79,3, HERE << "rock db opened " << path << ": FD " << TheFile); + debugs(79,3, HERE << "rock db opened " << DbName << ": FD " << TheFile); return true; } @@ -904,6 +912,7 @@ DiskerClose(const String &path) TheFile = -1; --store_open_disk_fd; } + DbName.clean(); } /// reports our needs for shared memory pages to Ipc::Mem::Pages