001: /*-
002: * See the file LICENSE for redistribution information.
003: *
004: * Copyright (c) 2002,2008 Oracle. All rights reserved.
005: *
006: * $Id: LogManagerTest.java,v 1.68.2.5 2008/01/07 15:14:29 cwl Exp $
007: */
008:
009: package com.sleepycat.je.log;
010:
011: import java.io.File;
012: import java.io.IOException;
013: import java.util.ArrayList;
014: import java.util.List;
015:
016: import junit.framework.TestCase;
017:
018: import com.sleepycat.je.DatabaseException;
019: import com.sleepycat.je.DbInternal;
020: import com.sleepycat.je.EnvironmentConfig;
021: import com.sleepycat.je.EnvironmentStats;
022: import com.sleepycat.je.StatsConfig;
023: import com.sleepycat.je.config.EnvironmentParams;
024: import com.sleepycat.je.dbi.EnvironmentImpl;
025: import com.sleepycat.je.log.entry.SingleItemEntry;
026: import com.sleepycat.je.util.TestUtils;
027: import com.sleepycat.je.utilint.DbLsn;
028: import com.sleepycat.je.utilint.Tracer;
029:
030: /**
031: * Test basic log management.
032: */
033: public class LogManagerTest extends TestCase {
034:
035: static private final boolean DEBUG = false;
036:
037: private FileManager fileManager;
038: private LogManager logManager;
039: private File envHome;
040: private EnvironmentImpl env;
041:
042: public LogManagerTest() {
043: super ();
044: envHome = new File(System.getProperty(TestUtils.DEST_DIR));
045: }
046:
047: public void setUp() throws DatabaseException, IOException {
048:
049: TestUtils.removeFiles("Setup", envHome, FileManager.JE_SUFFIX);
050: TestUtils.removeFiles("Setup", envHome, FileManager.DEL_SUFFIX);
051: }
052:
053: public void tearDown() throws IOException, DatabaseException {
054:
055: TestUtils.removeFiles("TearDown", envHome,
056: FileManager.JE_SUFFIX);
057: }
058:
059: /**
060: * Log and retrieve objects, with log in memory
061: */
062: public void testBasicInMemory() throws DatabaseException {
063:
064: EnvironmentConfig envConfig = TestUtils.initEnvConfig();
065: DbInternal.disableParameterValidation(envConfig);
066: envConfig.setConfigParam(EnvironmentParams.NODE_MAX.getName(),
067: "6");
068: envConfig.setConfigParam(EnvironmentParams.LOG_FILE_MAX
069: .getName(), "1000");
070:
071: envConfig.setAllowCreate(true);
072: env = new EnvironmentImpl(envHome, envConfig);
073: fileManager = env.getFileManager();
074: logManager = env.getLogManager();
075:
076: logAndRetrieve();
077: env.close();
078: }
079:
080: /**
081: * Log and retrieve objects, with log completely flushed to disk
082: */
083: public void testBasicOnDisk() throws Throwable {
084:
085: try {
086:
087: /*
088: * Force the buffers and files to be small. The log buffer is
089: * actually too small, will have to grow dynamically. Each file
090: * only holds one test item (each test item is 50 bytes).
091: */
092: EnvironmentConfig envConfig = TestUtils.initEnvConfig();
093: DbInternal.disableParameterValidation(envConfig);
094: envConfig.setConfigParam(EnvironmentParams.LOG_MEM_SIZE
095: .getName(),
096: EnvironmentParams.LOG_MEM_SIZE_MIN_STRING);
097: envConfig.setConfigParam(EnvironmentParams.NUM_LOG_BUFFERS
098: .getName(), "2");
099: envConfig.setConfigParam(EnvironmentParams.LOG_FILE_MAX
100: .getName(), "79");
101: envConfig.setConfigParam(EnvironmentParams.NODE_MAX
102: .getName(), "6");
103: envConfig.setConfigParam(EnvironmentParams.JE_LOGGING_LEVEL
104: .getName(), "CONFIG");
105:
106: /* Disable noisy UtilizationProfile database creation. */
107: DbInternal.setCreateUP(envConfig, false);
108: /* Don't checkpoint utilization info for this test. */
109: DbInternal.setCheckpointUP(envConfig, false);
110: /* Don't run the cleaner without a UtilizationProfile. */
111: envConfig.setConfigParam(EnvironmentParams.ENV_RUN_CLEANER
112: .getName(), "false");
113:
114: /*
115: * Don't run any daemons, those emit trace messages and other log
116: * entries and mess up our accounting.
117: */
118: turnOffDaemons(envConfig);
119: envConfig.setAllowCreate(true);
120:
121: /*
122: * Recreate the file manager and log manager w/different configs.
123: */
124: env = new EnvironmentImpl(envHome, envConfig);
125: fileManager = env.getFileManager();
126: logManager = env.getLogManager();
127:
128: logAndRetrieve();
129:
130: /*
131: * Expect 13 je files, 7 to hold logged records, 1 to hold root, 3
132: * to hold recovery messages, 2 for checkpoint records
133: */
134: String[] names = fileManager
135: .listFiles(FileManager.JE_SUFFIXES);
136: assertEquals("Should be 13 files on disk", 13, names.length);
137: } catch (Throwable t) {
138: t.printStackTrace();
139: throw t;
140: } finally {
141: env.close();
142: }
143: }
144:
145: /**
146: * Log and retrieve objects, with some of log flushed to disk, some of log
147: * in memory.
148: */
149: public void testComboDiskMemory() throws Throwable {
150:
151: try {
152:
153: /*
154: * Force the buffers and files to be small. The log buffer is
155: * actually too small, will have to grow dynamically. Each file
156: * only holds one test item (each test item is 50 bytes)
157: */
158: EnvironmentConfig envConfig = TestUtils.initEnvConfig();
159: DbInternal.disableParameterValidation(envConfig);
160: envConfig.setConfigParam(EnvironmentParams.LOG_MEM_SIZE
161: .getName(),
162: EnvironmentParams.LOG_MEM_SIZE_MIN_STRING);
163: envConfig.setConfigParam(EnvironmentParams.NUM_LOG_BUFFERS
164: .getName(), "2");
165: envConfig.setConfigParam(EnvironmentParams.JE_LOGGING_LEVEL
166: .getName(), "CONFIG");
167: envConfig.setConfigParam(EnvironmentParams.LOG_FILE_MAX
168: .getName(), "142");
169: envConfig.setConfigParam(EnvironmentParams.NODE_MAX
170: .getName(), "6");
171:
172: /* Disable noisy UtilizationProfile database creation. */
173: DbInternal.setCreateUP(envConfig, false);
174: /* Don't checkpoint utilization info for this test. */
175: DbInternal.setCheckpointUP(envConfig, false);
176: /* Don't run the cleaner without a UtilizationProfile. */
177: envConfig.setConfigParam(EnvironmentParams.ENV_RUN_CLEANER
178: .getName(), "false");
179:
180: /*
181: * Don't run the cleaner or the checkpointer daemons, those create
182: * more log entries and mess up our accounting
183: */
184: turnOffDaemons(envConfig);
185: envConfig.setAllowCreate(true);
186:
187: env = new EnvironmentImpl(envHome, envConfig);
188: fileManager = env.getFileManager();
189: logManager = env.getLogManager();
190:
191: logAndRetrieve();
192:
193: /*
194: * Expect 8 je files, 3 for records, 1 for root, 2 for recovery
195: * message, 2 for checkpoints.
196: */
197: String[] names = fileManager
198: .listFiles(FileManager.JE_SUFFIXES);
199: assertEquals("Should be 8 files on disk", 8, names.length);
200: } catch (Throwable t) {
201: t.printStackTrace();
202: throw t;
203: } finally {
204: env.close();
205: }
206: }
207:
208: /**
209: * Log and retrieve objects, with some of log flushed to disk, some
210: * of log in memory. Force the read buffer to be very small
211: */
212: public void testFaultingIn() throws Throwable {
213:
214: try {
215:
216: /*
217: * Force the buffers and files to be small. The log buffer is
218: * actually too small, will have to grow dynamically. We read in 32
219: * byte chunks, will have to re-read only holds one test item (each
220: * test item is 50 bytes)
221: */
222: EnvironmentConfig envConfig = TestUtils.initEnvConfig();
223: DbInternal.disableParameterValidation(envConfig);
224: envConfig.setConfigParam(EnvironmentParams.LOG_MEM_SIZE
225: .getName(),
226: EnvironmentParams.LOG_MEM_SIZE_MIN_STRING);
227: envConfig.setConfigParam(EnvironmentParams.NUM_LOG_BUFFERS
228: .getName(), "2");
229: envConfig.setConfigParam(EnvironmentParams.LOG_FILE_MAX
230: .getName(), "200");
231: envConfig.setConfigParam(
232: EnvironmentParams.LOG_FAULT_READ_SIZE.getName(),
233: "32");
234: envConfig.setConfigParam(EnvironmentParams.NODE_MAX
235: .getName(), "6");
236: envConfig.setAllowCreate(true);
237: env = new EnvironmentImpl(envHome, envConfig);
238: fileManager = env.getFileManager();
239: logManager = env.getLogManager();
240:
241: logAndRetrieve();
242: } catch (Throwable t) {
243: t.printStackTrace();
244: throw t;
245: } finally {
246: env.close();
247: }
248: }
249:
250: /**
251: * Log several objects, retrieve them.
252: */
253: private void logAndRetrieve() throws DatabaseException {
254:
255: /* Make test loggable objects. */
256:
257: List testRecs = new ArrayList();
258: for (int i = 0; i < 10; i++) {
259: testRecs.add(new Tracer("Hello there, rec " + (i + 1)));
260: }
261:
262: /* Log three of them, remember their LSNs. */
263: List testLsns = new ArrayList();
264:
265: for (int i = 0; i < 3; i++) {
266: long lsn = ((Tracer) testRecs.get(i)).log(logManager);
267: if (DEBUG) {
268: System.out.println("i = " + i + " test LSN: file = "
269: + DbLsn.getFileNumber(lsn) + " offset = "
270: + DbLsn.getFileOffset(lsn));
271: }
272: testLsns.add(new Long(lsn));
273: }
274:
275: /* Ask for them back, out of order. */
276: assertEquals((Tracer) testRecs.get(2), (Tracer) logManager
277: .get(DbLsn.longToLsn((Long) testLsns.get(2))));
278: assertEquals((Tracer) testRecs.get(0), (Tracer) logManager
279: .get(DbLsn.longToLsn((Long) testLsns.get(0))));
280: assertEquals((Tracer) testRecs.get(1), (Tracer) logManager
281: .get(DbLsn.longToLsn((Long) testLsns.get(1))));
282:
283: /* Intersperse logging and getting. */
284: testLsns.add(new Long(((Tracer) testRecs.get(3))
285: .log(logManager)));
286: testLsns.add(new Long(((Tracer) testRecs.get(4))
287: .log(logManager)));
288:
289: assertEquals((Tracer) testRecs.get(2), (Tracer) logManager
290: .get(DbLsn.longToLsn((Long) testLsns.get(2))));
291: assertEquals((Tracer) testRecs.get(4), (Tracer) logManager
292: .get(DbLsn.longToLsn((Long) testLsns.get(4))));
293:
294: /* Intersperse logging and getting. */
295: testLsns.add(new Long(((Tracer) testRecs.get(5))
296: .log(logManager)));
297: testLsns.add(new Long(((Tracer) testRecs.get(6))
298: .log(logManager)));
299: testLsns.add(new Long(((Tracer) testRecs.get(7))
300: .log(logManager)));
301:
302: assertEquals((Tracer) testRecs.get(7), (Tracer) logManager
303: .get(DbLsn.longToLsn((Long) testLsns.get(7))));
304: assertEquals((Tracer) testRecs.get(0), (Tracer) logManager
305: .get(DbLsn.longToLsn((Long) testLsns.get(0))));
306: assertEquals((Tracer) testRecs.get(6), (Tracer) logManager
307: .get(DbLsn.longToLsn((Long) testLsns.get(6))));
308: }
309:
310: private void turnOffDaemons(EnvironmentConfig envConfig) {
311: envConfig.setConfigParam(EnvironmentParams.ENV_RUN_CLEANER
312: .getName(), "false");
313: envConfig.setConfigParam(EnvironmentParams.ENV_RUN_CHECKPOINTER
314: .getName(), "false");
315: envConfig.setConfigParam(EnvironmentParams.ENV_RUN_EVICTOR
316: .getName(), "false");
317: envConfig.setConfigParam(EnvironmentParams.ENV_RUN_INCOMPRESSOR
318: .getName(), "false");
319: }
320:
321: /**
322: * Log a few items, then hit exceptions. Make sure LSN state is correctly
323: * maintained and that items logged after the exceptions are at the correct
324: * locations on disk.
325: */
326: public void testExceptions() throws Throwable {
327:
328: int logBufferSize = ((int) EnvironmentParams.LOG_MEM_SIZE_MIN) / 3;
329: int numLogBuffers = 5;
330: int logBufferMemSize = logBufferSize * numLogBuffers;
331: int logFileMax = 1000;
332: int okCounter = 0;
333:
334: try {
335: EnvironmentConfig envConfig = TestUtils.initEnvConfig();
336: DbInternal.disableParameterValidation(envConfig);
337: envConfig.setConfigParam(EnvironmentParams.LOG_MEM_SIZE
338: .getName(), new Integer(logBufferMemSize)
339: .toString());
340: envConfig.setConfigParam(EnvironmentParams.NUM_LOG_BUFFERS
341: .getName(), new Integer(numLogBuffers).toString());
342: envConfig.setConfigParam(EnvironmentParams.LOG_FILE_MAX
343: .getName(), new Integer(logFileMax).toString());
344: envConfig.setConfigParam(EnvironmentParams.NODE_MAX
345: .getName(), "6");
346: envConfig.setConfigParam(EnvironmentParams.JE_LOGGING_LEVEL
347: .getName(), "SEVERE");
348:
349: /* Disable noisy UtilizationProfile database creation. */
350: DbInternal.setCreateUP(envConfig, false);
351: /* Don't checkpoint utilization info for this test. */
352: DbInternal.setCheckpointUP(envConfig, false);
353: /* Don't run the cleaner without a UtilizationProfile. */
354: envConfig.setConfigParam(EnvironmentParams.ENV_RUN_CLEANER
355: .getName(), "false");
356:
357: /*
358: * Don't run any daemons, those emit trace messages and other log
359: * entries and mess up our accounting.
360: */
361: turnOffDaemons(envConfig);
362: envConfig.setAllowCreate(true);
363: env = new EnvironmentImpl(envHome, envConfig);
364: fileManager = env.getFileManager();
365: logManager = env.getLogManager();
366:
367: /* Keep track of items logged and their LSNs. */
368: ArrayList testRecs = new ArrayList();
369: ArrayList testLsns = new ArrayList();
370:
371: /*
372: * Intersperse:
373: * - log successfully
374: * - log w/failure because the item doesn't fit in the log buffer
375: * - have I/O failures writing out the log
376: * Verify that all expected items can be read. Some will come
377: * from the log buffer pool.
378: * Then close and re-open the environment, to verify that
379: * all log items are faulted from disk
380: */
381:
382: /* Successful log. */
383: addOkayItem(logManager, okCounter++, testRecs, testLsns,
384: logBufferSize);
385:
386: /* Item that's too big for the log buffers. */
387: attemptTooBigItem(logManager, logBufferSize, testRecs,
388: testLsns);
389:
390: /* Successful log. */
391: addOkayItem(logManager, okCounter++, testRecs, testLsns,
392: logBufferSize);
393:
394: /*
395: * This verify read the items from the log buffers. Note before SR
396: * #12638 existed (LSN state not restored properly after exception
397: * because of too-small log buffer), this verify hung.
398: */
399: verifyOkayItems(logManager, testRecs, testLsns, true);
400:
401: /* More successful logs, along with a few too-big items. */
402: for (; okCounter < 23; okCounter++) {
403: addOkayItem(logManager, okCounter, testRecs, testLsns,
404: logBufferSize);
405:
406: if ((okCounter % 4) == 0) {
407: attemptTooBigItem(logManager, logBufferSize,
408: testRecs, testLsns);
409: }
410: /*
411: * If we verify in the loop, sometimes we'll read from disk and
412: * sometimes from the log buffer pool.
413: */
414: verifyOkayItems(logManager, testRecs, testLsns, true);
415: }
416:
417: /*
418: * Test the case where we flip files and write the old write buffer
419: * out before we try getting a log buffer for the new item. We need
420: * to
421: *
422: * - hit a log-too-small exceptin
423: * - right after, we need to log an item that is small enough
424: * to fit in the log buffer but big enough to require that
425: * we flip to a new file.
426: */
427: long nextLsn = fileManager.getNextLsn();
428: long fileOffset = DbLsn.getFileOffset(nextLsn);
429:
430: assertTrue((logFileMax - fileOffset) < logBufferSize);
431: attemptTooBigItem(logManager, logBufferSize, testRecs,
432: testLsns);
433: addOkayItem(logManager, okCounter++, testRecs, testLsns,
434: logBufferSize, ((int) (logFileMax - fileOffset)));
435: verifyOkayItems(logManager, testRecs, testLsns, true);
436:
437: /* Invoke some i/o exceptions. */
438: for (; okCounter < 50; okCounter++) {
439: attemptIOException(logManager, fileManager, testRecs,
440: testLsns, false);
441: addOkayItem(logManager, okCounter, testRecs, testLsns,
442: logBufferSize);
443: verifyOkayItems(logManager, testRecs, testLsns, false);
444: }
445:
446: /*
447: * Finally, close this environment and re-open, and read all
448: * expected items from disk.
449: */
450: env.close();
451: envConfig.setAllowCreate(false);
452: env = new EnvironmentImpl(envHome, envConfig);
453: fileManager = env.getFileManager();
454: logManager = env.getLogManager();
455: verifyOkayItems(logManager, testRecs, testLsns, false);
456:
457: /* Check that we read these items off disk. */
458: EnvironmentStats stats = new EnvironmentStats();
459: StatsConfig config = new StatsConfig();
460: logManager.loadStats(config, stats);
461: assertTrue(stats.getEndOfLog() > 0);
462: assertTrue(stats.getNNotResident() >= testRecs.size());
463:
464: } catch (Throwable t) {
465: t.printStackTrace();
466: throw t;
467: } finally {
468: env.close();
469: }
470: }
471:
472: private void addOkayItem(LogManager logManager, int tag,
473: List testRecs, List testLsns, int logBufferSize,
474: int fillerLen) throws DatabaseException {
475:
476: String filler = new String(new byte[fillerLen]);
477: Tracer t = new Tracer("okay" + filler + tag);
478: assertTrue(logBufferSize > t.getLogSize());
479: testRecs.add(t);
480: long lsn = t.log(logManager);
481: testLsns.add(new Long(lsn));
482: }
483:
484: private void addOkayItem(LogManager logManager, int tag,
485: List testRecs, List testLsns, int logBufferSize)
486: throws DatabaseException {
487:
488: addOkayItem(logManager, tag, testRecs, testLsns, logBufferSize,
489: 0);
490: }
491:
492: private void attemptTooBigItem(LogManager logManager,
493: int logBufferSize, Tracer big, List testRecs, List testLsns) {
494: assertTrue(big.getLogSize() > logBufferSize);
495:
496: try {
497: long lsn = big.log(logManager);
498: testLsns.add(new Long(lsn));
499: testRecs.add(big);
500: } catch (DatabaseException expected) {
501: fail("Should not have hit exception.");
502: }
503: }
504:
505: private void attemptTooBigItem(LogManager logManager,
506: int logBufferSize, List testRecs, List testLsns) {
507: String stuff = "12345679890123456798901234567989012345679890";
508: while (stuff.length() < EnvironmentParams.LOG_MEM_SIZE_MIN) {
509: stuff += stuff;
510: }
511: Tracer t = new Tracer(stuff);
512: attemptTooBigItem(logManager, logBufferSize, t, testRecs,
513: testLsns);
514: }
515:
516: private void attemptIOException(LogManager logManager,
517: FileManager fileManager, List testRecs, List testLsns,
518: boolean forceFlush) {
519: Tracer t = new Tracer("ioException");
520: FileManager.IO_EXCEPTION_TESTING_ON_WRITE = true;
521: try {
522:
523: /*
524: * This object might get flushed to disk -- depend on whether
525: * the ioexception happened before or after the copy into the
526: * log buffer. Both are valid, but the test doesn't yet
527: * know how to differentiate the cases.
528:
529: testLsns.add(new Long(fileManager.getNextLsn()));
530: testRecs.add(t);
531: */
532: logManager.logForceFlush(new SingleItemEntry(
533: LogEntryType.LOG_TRACE, t), true);
534: fail("expect io exception");
535: } catch (DatabaseException expected) {
536: } finally {
537: FileManager.IO_EXCEPTION_TESTING_ON_WRITE = false;
538: }
539: }
540:
541: private void verifyOkayItems(LogManager logManager,
542: ArrayList testRecs, ArrayList testLsns, boolean checkOrder)
543: throws DatabaseException {
544:
545: /* read forwards. */
546: for (int i = 0; i < testRecs.size(); i++) {
547: assertEquals((Tracer) testRecs.get(i), (Tracer) logManager
548: .get(DbLsn.longToLsn((Long) testLsns.get(i))));
549:
550: }
551:
552: /* Make sure LSNs are adjacent */
553: assertEquals(testLsns.size(), testRecs.size());
554:
555: if (checkOrder) {
556:
557: /*
558: * TODO: sometimes an ioexception entry will make it into the write
559: * buffer, and sometimes it won't. It depends on whether the IO
560: * exception was thrown when before or after the logabble item was
561: * written into the buffer. I haven't figure out yet how to tell
562: * the difference, so for now, we don't check order in the portion
563: * of the test that issues IO exceptions.
564: */
565: for (int i = 1; i < testLsns.size(); i++) {
566:
567: long lsn = ((Long) testLsns.get(i)).longValue();
568: long lsnFile = DbLsn.getFileNumber(lsn);
569: long lsnOffset = DbLsn.getFileOffset(lsn);
570: long prevLsn = ((Long) testLsns.get(i - 1)).longValue();
571: long prevFile = DbLsn.getFileNumber(prevLsn);
572: long prevOffset = DbLsn.getFileOffset(prevLsn);
573: if (prevFile == lsnFile) {
574: assertEquals(
575: "item " + i + "prev = "
576: + DbLsn.toString(prevLsn)
577: + " current=" + DbLsn.toString(lsn),
578: (((Tracer) testRecs.get(i - 1))
579: .getLogSize() + LogEntryHeader.MIN_HEADER_SIZE),
580: lsnOffset - prevOffset);
581: } else {
582: assertEquals(prevFile + 1, lsnFile);
583: assertEquals(FileManager.firstLogEntryOffset(),
584: lsnOffset);
585: }
586: }
587: }
588:
589: /* read backwards. */
590: for (int i = testRecs.size() - 1; i > -1; i--) {
591: assertEquals((Tracer) testRecs.get(i), (Tracer) logManager
592: .get(DbLsn.longToLsn((Long) testLsns.get(i))));
593:
594: }
595: }
596: }
|