Hello,
The attached trunk patch fixes bug 3819 in our tests.
Please note that the underlying problem may lead to other assertions,
including "NumberOfUFSDirs" in UFSSwapDir and "fd >= 0" in file_close().
Since trunk r9181.3.1, reconfiguration is done in at least two steps:
First, mainReconfigureStart() closes/cleans/disables all modules
supporting hot reconfiguration and then, at the end of the event loop
iteration, mainReconfigureFinish() opens/configures/enables them again.
UFS code hits assertions if it has to log entries or rebuild swap.state
between those two steps. The patch disables or delays those activities
during reconfiguration.
The tiny assertion opportunity window hides these bugs from most proxies
that are not doing enough disk I/O or are not being reconfigured
frequently enough.
HTH,
Alex.
Bug 3819: "fd >= 0" assertion in file_write() during reconfiguration
Other possible assertions include "NumberOfUFSDirs" in UFSSwapDir and
"fd >= 0" in file_close().
Since trunk r9181.3.1, reconfiguration is done in at least two steps:
First, mainReconfigureStart() closes/cleans/disables all modules
supporting hot reconfiguration and then, at the end of the event loop
iteration, mainReconfigureFinish() opens/configures/enables them again.
UFS code hits assertions if it has to log entries or rebuild swap.state
between those two steps. The tiny assertion opportunity window hides
these bugs from most proxies that are not doing enough disk I/O or are
not being reconfigured frequently enough.
Asynchronous UFS cache_dirs such as diskd were the most exposed, but
even blocking UFS caching code could probably hit [rebuild] assertions.
The swap.state rebuilding (always initiated at startup) probably did not
work as intended if reconfiguration happened during the rebuild time
because reconfiguration closed the swap.state file being rebuilt. We now
protect that swap.state file and delay rebuilding progress until
reconfiguration is over.
TODO: To squash more similar bugs, we need to move hot reconfiguration
support into the modules so that each module can reconfigure instantly.
=== modified file 'src/fs/ufs/RebuildState.cc'
--- src/fs/ufs/RebuildState.cc 2016-04-03 23:41:58 +0000
+++ src/fs/ufs/RebuildState.cc 2016-09-16 01:17:04 +0000
@@ -74,43 +74,45 @@ Fs::Ufs::RebuildState::RebuildState(RefC
if (!clean)
flags.need_to_validate = true;
debugs(47, DBG_IMPORTANT, "Rebuilding storage in " << sd->path << " (" <<
(clean ? "clean log" : (LogParser ? "dirty log" : "no log")) << ")");
}
Fs::Ufs::RebuildState::~RebuildState()
{
sd->closeTmpSwapLog();
if (LogParser)
delete LogParser;
}
void
Fs::Ufs::RebuildState::RebuildStep(void *data)
{
RebuildState *rb = (RebuildState *)data;
- rb->rebuildStep();
+ if (!reconfiguring)
+ rb->rebuildStep();
- if (!rb->isDone())
+ // delay storeRebuildComplete() when reconfiguring to protect storeCleanup()
+ if (!rb->isDone() || reconfiguring)
eventAdd("storeRebuild", RebuildStep, rb, 0.01, 1);
else {
-- StoreController::store_dirs_rebuilding;
storeRebuildComplete(&rb->counts);
delete rb;
}
}
/// load entries from swap.state or files until we run out of entries or time
void
Fs::Ufs::RebuildState::rebuildStep()
{
currentEntry(NULL);
// Balance our desire to maximize the number of entries processed at once
// (and, hence, minimize overheads and total rebuild time) with a
// requirement to also process Coordinator events, disk I/Os, etc.
const int maxSpentMsec = 50; // keep small: most RAM I/Os are under 1ms
const timeval loopStart = current_time;
=== modified file 'src/fs/ufs/UFSSwapDir.cc'
--- src/fs/ufs/UFSSwapDir.cc 2016-04-03 23:41:58 +0000
+++ src/fs/ufs/UFSSwapDir.cc 2016-09-16 01:05:19 +0000
@@ -300,41 +300,42 @@ Fs::Ufs::UFSSwapDir::init()
void
Fs::Ufs::UFSSwapDir::create()
{
debugs(47, 3, "Creating swap space in " << path);
createDirectory(path, 0);
createSwapSubDirs();
}
Fs::Ufs::UFSSwapDir::UFSSwapDir(char const *aType, const char *anIOType) :
SwapDir(aType),
IO(NULL),
fsdata(NULL),
map(new FileMap()),
suggest(0),
l1(16),
l2(256),
swaplog_fd(-1),
currentIOOptions(new ConfigOptionVector()),
ioType(xstrdup(anIOType)),
cur_size(0),
- n_disk_objects(0)
+ n_disk_objects(0),
+ rebuilding_(false)
{
/* modulename is only set to disk modules that are built, by configure,
* so the Find call should never return NULL here.
*/
IO = new Fs::Ufs::UFSStrategy(DiskIOModule::Find(anIOType)->createStrategy());
}
Fs::Ufs::UFSSwapDir::~UFSSwapDir()
{
if (swaplog_fd > -1) {
file_close(swaplog_fd);
swaplog_fd = -1;
}
xfree(ioType);
delete map;
delete IO;
delete currentIOOptions;
}
void
@@ -708,78 +709,81 @@ Fs::Ufs::UFSSwapDir::logFile(char const
if (strncmp(lpath, Config.Log.swap, MAXPATHLEN - 64) == 0) {
strcat(lpath, ".");
snprintf(digit, 32, "%02d", index);
strncat(lpath, digit, 3);
}
} else {
xstrncpy(lpath, path, MAXPATHLEN - 64);
strcat(lpath, "/swap.state");
}
if (ext)
strncat(lpath, ext, 16);
return lpath;
}
void
Fs::Ufs::UFSSwapDir::openLog()
{
+ assert(NumberOfUFSDirs || !UFSDirToGlobalDirMapping);
+ ++NumberOfUFSDirs;
+ assert(NumberOfUFSDirs <= Config.cacheSwap.n_configured);
+
+ if (rebuilding_) { // we did not close the temporary log used for rebuilding
+ assert(swaplog_fd >= 0);
+ return;
+ }
+
char *logPath;
logPath = logFile();
swaplog_fd = file_open(logPath, O_WRONLY | O_CREAT | O_BINARY);
if (swaplog_fd < 0) {
int xerrno = errno;
debugs(50, DBG_IMPORTANT, "ERROR opening swap log " << logPath << ": " << xstrerr(xerrno));
fatal("UFSSwapDir::openLog: Failed to open swap log.");
}
debugs(50, 3, HERE << "Cache Dir #" << index << " log opened on FD " << swaplog_fd);
-
- if (0 == NumberOfUFSDirs)
- assert(NULL == UFSDirToGlobalDirMapping);
-
- ++NumberOfUFSDirs;
-
- assert(NumberOfUFSDirs <= Config.cacheSwap.n_configured);
}
void
Fs::Ufs::UFSSwapDir::closeLog()
{
if (swaplog_fd < 0) /* not open */
return;
+ --NumberOfUFSDirs;
+ assert(NumberOfUFSDirs >= 0);
+ if (!NumberOfUFSDirs)
+ safe_free(UFSDirToGlobalDirMapping);
+
+ if (rebuilding_) // we cannot close the temporary log used for rebuilding
+ return;
+
file_close(swaplog_fd);
debugs(47, 3, "Cache Dir #" << index << " log closed on FD " << swaplog_fd);
swaplog_fd = -1;
-
- --NumberOfUFSDirs;
-
- assert(NumberOfUFSDirs >= 0);
-
- if (0 == NumberOfUFSDirs)
- safe_free(UFSDirToGlobalDirMapping);
}
bool
Fs::Ufs::UFSSwapDir::validL1(int anInt) const
{
return anInt < l1;
}
bool
Fs::Ufs::UFSSwapDir::validL2(int anInt) const
{
return anInt < l2;
}
StoreEntry *
Fs::Ufs::UFSSwapDir::addDiskRestore(const cache_key * key,
sfileno file_number,
uint64_t swap_file_sz,
time_t expires,
time_t timestamp,
@@ -825,100 +829,106 @@ Fs::Ufs::UFSSwapDir::undoAddDiskRestore(
debugs(47, 5, HERE << *e);
replacementRemove(e); // checks swap_dirn so do it before we invalidate it
// Do not unlink the file as it might be used by a subsequent entry.
mapBitReset(e->swap_filen);
e->swap_filen = -1;
e->swap_dirn = -1;
cur_size -= fs.blksize * sizeInBlocks(e->swap_file_sz);
--n_disk_objects;
}
void
Fs::Ufs::UFSSwapDir::rebuild()
{
++StoreController::store_dirs_rebuilding;
eventAdd("storeRebuild", Fs::Ufs::RebuildState::RebuildStep, new Fs::Ufs::RebuildState(this), 0.0, 1);
}
void
Fs::Ufs::UFSSwapDir::closeTmpSwapLog()
{
+ assert(rebuilding_);
+ rebuilding_ = false;
+
char *swaplog_path = xstrdup(logFile(NULL)); // where the swaplog should be
char *tmp_path = xstrdup(logFile(".new")); // the temporary file we have generated
int fd;
file_close(swaplog_fd);
if (xrename(tmp_path, swaplog_path) < 0) {
fatalf("Failed to rename log file %s to %s", tmp_path, swaplog_path);
}
fd = file_open(swaplog_path, O_WRONLY | O_CREAT | O_BINARY);
if (fd < 0) {
int xerrno = errno;
debugs(50, DBG_IMPORTANT, "ERROR: " << swaplog_path << ": " << xstrerr(xerrno));
fatalf("Failed to open swap log %s", swaplog_path);
}
xfree(swaplog_path);
xfree(tmp_path);
swaplog_fd = fd;
debugs(47, 3, "Cache Dir #" << index << " log opened on FD " << fd);
}
FILE *
Fs::Ufs::UFSSwapDir::openTmpSwapLog(int *clean_flag, int *zero_flag)
{
+ assert(!rebuilding_);
+
char *swaplog_path = xstrdup(logFile(NULL));
char *clean_path = xstrdup(logFile(".last-clean"));
char *new_path = xstrdup(logFile(".new"));
struct stat log_sb;
struct stat clean_sb;
FILE *fp;
int fd;
if (::stat(swaplog_path, &log_sb) < 0) {
debugs(47, DBG_IMPORTANT, "Cache Dir #" << index << ": No log file");
safe_free(swaplog_path);
safe_free(clean_path);
safe_free(new_path);
return NULL;
}
*zero_flag = log_sb.st_size == 0 ? 1 : 0;
/* close the existing write-only FD */
if (swaplog_fd >= 0)
file_close(swaplog_fd);
/* open a write-only FD for the new log */
fd = file_open(new_path, O_WRONLY | O_CREAT | O_TRUNC | O_BINARY);
if (fd < 0) {
int xerrno = errno;
debugs(50, DBG_IMPORTANT, "ERROR: while opening swap log" << new_path << ": " << xstrerr(xerrno));
fatalf("Failed to open swap log %s", new_path);
}
swaplog_fd = fd;
+ rebuilding_ = true;
{
const StoreSwapLogHeader header;
MemBuf buf;
buf.init(header.record_size, header.record_size);
buf.append(reinterpret_cast<const char*>(&header), sizeof(header));
// Pad to keep in sync with UFSSwapDir::writeCleanStart().
memset(buf.space(), 0, header.gapSize());
buf.appended(header.gapSize());
file_write(swaplog_fd, -1, buf.content(), buf.contentSize(),
NULL, NULL, buf.freeFunc());
}
/* open a read-only stream of the old log */
fp = fopen(swaplog_path, "rb");
if (!fp) {
int xerrno = errno;
debugs(50, DBG_CRITICAL, "ERROR: while opening " << swaplog_path << ": " << xstrerr(xerrno));
fatalf("Failed to open swap log for reading %s", swaplog_path);
@@ -1043,52 +1053,51 @@ Fs::Ufs::UFSSwapDir::writeCleanDone()
else
file_close(file_open(state->cln, O_WRONLY | O_CREAT | O_TRUNC | O_BINARY));
/* close */
safe_free(state->cur);
safe_free(state->newLog);
safe_free(state->cln);
if (state->fd >= 0)
file_close(state->fd);
state->fd = -1;
delete state;
cleanLog = NULL;
}
-void
-Fs::Ufs::UFSSwapDir::CleanEvent(void *)
+/// safely cleans a few unused files if possible
+int
+Fs::Ufs::UFSSwapDir::HandleCleanEvent()
{
static int swap_index = 0;
int i;
int j = 0;
int n = 0;
- /*
- * Assert that there are UFS cache_dirs configured, otherwise
- * we should never be called.
- */
- assert(NumberOfUFSDirs);
+
+ if (!NumberOfUFSDirs)
+ return 0; // probably in the middle of reconfiguration
if (NULL == UFSDirToGlobalDirMapping) {
SwapDir *sd;
/*
* Initialize the little array that translates UFS cache_dir
* number into the Config.cacheSwap.swapDirs array index.
*/
UFSDirToGlobalDirMapping = (int *)xcalloc(NumberOfUFSDirs, sizeof(*UFSDirToGlobalDirMapping));
for (i = 0, n = 0; i < Config.cacheSwap.n_configured; ++i) {
/* This is bogus, the controller should just clean each instance once */
sd = dynamic_cast <SwapDir *>(INDEXSD(i));
if (!UFSSwapDir::IsUFSDir(sd))
continue;
UFSSwapDir *usd = dynamic_cast<UFSSwapDir *>(sd);
assert (usd);
@@ -1098,40 +1107,47 @@ Fs::Ufs::UFSSwapDir::CleanEvent(void *)
j += (usd->l1 * usd->l2);
}
assert(n == NumberOfUFSDirs);
/*
* Start the commonUfsDirClean() swap_index with a random
* value. j equals the total number of UFS level 2
* swap directories
*/
std::mt19937 mt(static_cast<uint32_t>(getCurrentTime() & 0xFFFFFFFF));
xuniform_int_distribution<> dist(0, j);
swap_index = dist(mt);
}
/* if the rebuild is finished, start cleaning directories. */
if (0 == StoreController::store_dirs_rebuilding) {
n = DirClean(swap_index);
++swap_index;
}
+ return n;
+}
+
+void
+Fs::Ufs::UFSSwapDir::CleanEvent(void *)
+{
+ const int n = HandleCleanEvent();
eventAdd("storeDirClean", CleanEvent, NULL,
15.0 * exp(-0.25 * n), 1);
}
bool
Fs::Ufs::UFSSwapDir::IsUFSDir(SwapDir * sd)
{
UFSSwapDir *mySD = dynamic_cast<UFSSwapDir *>(sd);
return (mySD != 0) ;
}
/*
* XXX: this is broken - it assumes all cache dirs use the same
* l1 and l2 scheme. -RBC 20021215. Partial fix is in place -
* if not UFSSwapDir return 0;
*/
bool
Fs::Ufs::UFSSwapDir::FilenoBelongsHere(int fn, int F0, int F1, int F2)
{
int D1, D2;
@@ -1267,40 +1283,45 @@ Fs::Ufs::UFSSwapDir::callback()
{
return IO->callback();
}
void
Fs::Ufs::UFSSwapDir::sync()
{
IO->sync();
}
void
Fs::Ufs::UFSSwapDir::swappedOut(const StoreEntry &e)
{
cur_size += fs.blksize * sizeInBlocks(e.swap_file_sz);
++n_disk_objects;
}
void
Fs::Ufs::UFSSwapDir::logEntry(const StoreEntry & e, int op) const
{
+ if (swaplog_fd < 0) {
+ debugs(36, 5, "cannot log " << e << " in the middle of reconfiguration");
+ return;
+ }
+
StoreSwapLogData *s = new StoreSwapLogData;
s->op = (char) op;
s->swap_filen = e.swap_filen;
s->timestamp = e.timestamp;
s->lastref = e.lastref;
s->expires = e.expires;
s->lastmod = e.lastmod;
s->swap_file_sz = e.swap_file_sz;
s->refcount = e.refcount;
s->flags = e.flags;
memcpy(s->key, e.key, SQUID_MD5_DIGEST_LENGTH);
s->finalize();
file_write(swaplog_fd,
-1,
s,
sizeof(StoreSwapLogData),
NULL,
NULL,
FreeObject);
}
=== modified file 'src/fs/ufs/UFSSwapDir.h'
--- src/fs/ufs/UFSSwapDir.h 2016-07-23 13:36:56 +0000
+++ src/fs/ufs/UFSSwapDir.h 2016-09-16 01:05:19 +0000
@@ -109,45 +109,47 @@ public:
bool validL2(int) const;
bool validL1(int) const;
/** Add and remove the given StoreEntry from the replacement policy in use */
void replacementAdd(StoreEntry *e);
void replacementRemove(StoreEntry *e);
protected:
FileMap *map;
int suggest;
int l1;
int l2;
private:
void parseSizeL1L2();
static int NumberOfUFSDirs;
static int * UFSDirToGlobalDirMapping;
bool pathIsDirectory(const char *path)const;
int swaplog_fd;
static EVH CleanEvent;
+ static int HandleCleanEvent();
/** Verify that the the CacheDir exists
*
* If this returns < 0, then Squid exits, complains about swap
* directories not existing, and instructs the admin to run 'squid -z'
* Called by UFSSwapDir::init
*/
bool verifyCacheDirs();
void rebuild();
int createDirectory(const char *path, int);
void createSwapSubDirs();
void dumpEntry(StoreEntry &) const;
char *logFile(char const *ext = NULL)const;
void changeIO(DiskIOModule *);
bool optionIOParse(char const *option, const char *value, int reconfiguring);
void optionIODump(StoreEntry * e) const;
mutable ConfigOptionVector *currentIOOptions;
char const *ioType;
uint64_t cur_size; ///< currently used space in the storage area
uint64_t n_disk_objects; ///< total number of objects stored
+ bool rebuilding_; ///< whether RebuildState is writing the new swap.state
};
} //namespace Ufs
} //namespace Fs
#endif /* SQUID_FS_UFS_UFSSWAPDIR_H */
=== modified file 'src/store/Disks.cc'
--- src/store/Disks.cc 2016-07-23 13:36:56 +0000
+++ src/store/Disks.cc 2016-09-16 01:05:19 +0000
@@ -565,41 +565,41 @@ storeDirCloseSwapLogs()
* Writes a "clean" swap log file from in-memory metadata.
* This is a rewrite of the original function to troll each
* StoreDir and write the logs, and flush at the end of
* the run. Thanks goes to Eric Stern, since this solution
* came out of his COSS code.
*/
int
storeDirWriteCleanLogs(int reopen)
{
const StoreEntry *e = NULL;
int n = 0;
struct timeval start;
double dt;
RefCount<SwapDir> sd;
int dirn;
int notdone = 1;
// Check for store_dirs_rebuilding because fatal() often calls us in early
// initialization phases, before store log is initialized and ready. Also,
- // some stores probably do not support log cleanup during Store rebuilding.
+ // some stores do not support log cleanup during Store rebuilding.
if (StoreController::store_dirs_rebuilding) {
debugs(20, DBG_IMPORTANT, "Not currently OK to rewrite swap log.");
debugs(20, DBG_IMPORTANT, "storeDirWriteCleanLogs: Operation aborted.");
return 0;
}
debugs(20, DBG_IMPORTANT, "storeDirWriteCleanLogs: Starting...");
getCurrentTime();
start = current_time;
for (dirn = 0; dirn < Config.cacheSwap.n_configured; ++dirn) {
sd = dynamic_cast<SwapDir *>(INDEXSD(dirn));
if (sd->writeCleanStart() < 0) {
debugs(20, DBG_IMPORTANT, "log.clean.start() failed for dir #" << sd->index);
continue;
}
}
/*
_______________________________________________
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev
