1 /*
   2  * $Id$
   3  *
   4  * Copyright (c) 2001, 2010, Oracle and/or its affiliates. All rights reserved.
   5  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
   6  *
   7  * This code is free software; you can redistribute it and/or modify it
   8  * under the terms of the GNU General Public License version 2 only, as
   9  * published by the Free Software Foundation.  Oracle designates this
  10  * particular file as subject to the "Classpath" exception as provided
  11  * by Oracle in the LICENSE file that accompanied this code.
  12  *
  13  * This code is distributed in the hope that it will be useful, but WITHOUT
  14  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  15  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  16  * version 2 for more details (a copy is included in the LICENSE file that
  17  * accompanied this code).
  18  *
  19  * You should have received a copy of the GNU General Public License version
  20  * 2 along with this work; if not, write to the Free Software Foundation,
  21  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  22  *
  23  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  24  * or visit www.oracle.com if you need additional information or have any
  25  * questions.
  26  */
  27 package com.sun.javatest;
  28 
  29 import java.io.File;
  30 import java.io.IOException;
  31 import java.io.RandomAccessFile;
  32 import java.lang.ref.WeakReference;
  33 import java.util.Iterator;
  34 import java.util.Map;
  35 import java.util.TreeMap;
  36 
  37 import com.sun.javatest.logging.WorkDirLogHandler;
  38 import com.sun.javatest.util.Debug;
  39 import com.sun.javatest.util.Fifo;
  40 import com.sun.javatest.util.I18NResourceBundle;
  41 
  42 import java.util.logging.Handler;
  43 import java.util.logging.Logger;
  44 
  45 /**
  46  * Class which maintains a cache of the results currently existing inside a
  47  * work directory.  It is designed to allow the harness to get general
  48  * information (name, status) about tests without having to open all the
  49  * result files.
  50  */
  51 public class TestResultCache {
  52 
  53     /**
  54      * Interface which allows an external class to monitor the cache's
  55      * activities.
  56      */
  57     public static interface Observer {
  58         /**
  59          * Called when tests have been read from the cache file.
  60          * @param tests the tests that have been read
  61          */
  62         void update(Map<String, TestResult> tests);
  63 
  64         /**
  65          * Called periodically while waiting to access the cache.
  66          * @param timeSoFar the time so far that a client has been waiting to
  67          * access the cache
  68          */
  69         void waitingForLock(long timeSoFar);
  70 
  71         /**
  72          * Called when the timed out waiting for access to the cache.
  73          */
  74         void timeoutWaitingForLock();
  75 
  76         /**
  77          * Called when the cache has been locked.
  78          */
  79         void acquiredLock();
  80 
  81         /**
  82          * Called when the lock on the cache has been released.
  83          */
  84         void releasedLock();
  85 
  86         /**
  87          * Called when starting to (re)build the cache.
  88          * @param reset currently, always true
  89          */
  90         void buildingCache(boolean reset);
  91 
  92         /**
  93          * Called when a test has been found to put in the cache.
  94          * @param tr the test that is being put in the cache
  95          */
  96         void buildingCache(TestResult tr);
  97 
  98         /**
  99          * Called when the cache has been (re)built.
 100          */
 101         void builtCache();
 102 
 103         /**
 104          * Called when a serious error has occurred and the cache is unable to continue.
 105          * @param t an object identifying the error that occurred
 106          */
 107         void error(Throwable t);
 108     };
 109 
 110     /**
 111      * Primary constructor for a cache.
 112      * @param workDir the work directory to attach to
 113      * @param observer the observer to notify of cache events
 114      * @throws IOException if an error occurs reading the cache file
 115      */
 116     public TestResultCache(WorkDirectory workDir, Observer observer)
 117                             throws IOException {
 118         this.workDir = workDir;
 119         this.observer = observer;
 120 
 121         weakWorkDir = new WeakReference<>(workDir);
 122         weakObserver = new WeakReference<>(observer);
 123 
 124         cacheFile = workDir.getSystemFile(V2_FILENAME);
 125         lockFile = workDir.getSystemFile(V2_LOCKNAME);
 126 
 127         File old = workDir.getSystemFile(V1_FILENAME);
 128         if (old.exists()) {
 129             workDir.log(i18n, "trc.rmCachev1", old.getAbsolutePath());
 130             old.delete();
 131         }
 132 
 133         old = workDir.getSystemFile(V1_LOCKNAME);
 134         if (old.exists()) {
 135             workDir.log(i18n, "trc.rmLockv1", old.getAbsolutePath());
 136             old.delete();
 137         }
 138 
 139         raf = new RandomAccessFile(cacheFile, "rw");
 140 
 141         worker = new Thread() {
 142                 public void run() {
 143                     doWorkUntilDone();
 144                 }
 145             };
 146         worker.setName("TestResultCache.worker" + (workerNumber++) + "[" + workDir.getRoot() + "]");
 147         worker.setDaemon(true); // allows thread to run during shutdown
 148 
 149         // ensure priority is lower than that of the calling thread, but don't
 150         // want priority too low because we want cache updated in a timely fashion
 151         int prio = Math.max(0, Math.min(Thread.currentThread().getPriority() - 1, 3));
 152         worker.setPriority(prio);
 153 
 154         worker.start();
 155 
 156         shutdownHandler = new Thread() {
 157                 public void run() {
 158                     shutdown();
 159                 }
 160             };
 161         Runtime.getRuntime().addShutdownHook(shutdownHandler);
 162     }
 163 
 164     /**
 165      * Insert a test result into the cache.
 166      * The cache file will be updated asynchronously.
 167      * @param tr the test to be inserted.
 168      **/
 169     synchronized void insert(TestResult tr) {
 170         if (DEBUG_TESTS)
 171             Debug.println("TRC.insert " + tr.getWorkRelativePath() + " " + tr.getStatus());
 172 
 173         reviveWeakReferences();
 174         testsToWrite.insert(tr);
 175         notifyAll();
 176     }
 177 
 178     /**
 179      * Request an update via the observer of all the tests in the cache.
 180      */
 181     synchronized void requestFullUpdate() {
 182         if (!shutdownRequested) {
 183             reviveWeakReferences();
 184             fullUpdateRequested = true;
 185             notifyAll();
 186         }
 187     }
 188 
 189     /**
 190      * Check if a call to compress the cache is advised.
 191      */
 192     synchronized boolean needsCompress() {
 193         return compressNeeded;
 194     }
 195 
 196     /**
 197      * Compress the cache file, eliminating any obsolete entries.
 198      * The cache file will be updated asynchronously.
 199      */
 200     synchronized void compress() {
 201         if (!shutdownRequested) {
 202             reviveWeakReferences();
 203             compressRequested = true;
 204             notifyAll();
 205         }
 206     }
 207 
 208     /**
 209      * Expedite any outstanding updates to the cache file.
 210      * The cache file will be updated asynchronously.
 211      */
 212     synchronized void flush() {
 213         reviveWeakReferences();
 214         flushRequested = true;
 215         notifyAll();
 216     }
 217 
 218     boolean workerAlive() {
 219         return worker != null;
 220     }
 221 
 222     //-------------------------------------------------------------------------------------
 223     //
 224     // the main worker code
 225 
 226     private static final int DEFAULT_COMPRESS_PERCENT_LEVEL = 40;
 227 
 228     private void doWorkUntilDone() {
 229         int compressPercentLevel =
 230             Integer.getInteger("javatest.trc.cacheThreshold",
 231                                DEFAULT_COMPRESS_PERCENT_LEVEL).intValue();
 232         compressPercentLevel = Math.max(1, Math.min(compressPercentLevel, 100));
 233 
 234         boolean haveWork = true;  // first time in, we need to read/build the cache
 235         fullUpdateRequested = true; // first time in, update client when initialized
 236 
 237         try {
 238             while (haveWork) {
 239                 doWork();
 240 
 241                 synchronized (this) {
 242                     if (flushRequested && testsToWrite.size() == 0)
 243                         flushRequested = false;
 244 
 245                     long timeLastWork = System.currentTimeMillis();
 246                     haveWork = isWorkAvailable(timeLastWork);
 247                     while (!haveWork && !shutdownRequested) {
 248                         workDir = null;
 249                         observer = null;
 250 
 251                         if (DEBUG_SYNC)
 252                             Debug.println("TRC.worker waiting");
 253 
 254                         wait(MIN_TEST_READ_INTERVAL);
 255                         haveWork = isWorkAvailable(timeLastWork);
 256 
 257                         if (DEBUG_SYNC)
 258                             Debug.println("TRC.worker awake haveWork=" + haveWork);
 259                     }
 260 
 261                     // wake up the workDir and observer (if still available)
 262                     reviveWeakReferences();
 263 
 264                     // if workDir and/or observer are null, then the WD and TRT
 265                     // that opened this cache have been GC-ed. This means that this
 266                     // thread has woken up for an external reason, such as noticing
 267                     // that the cache file size has changed.  Since the client has
 268                     // gone away, there is nothing left to do but return.
 269                     if (workDir == null || observer == null)
 270                         return;
 271 
 272                     // re-evaluate compressNeeded now, while still synchronized
 273                     // so that totalEntryCount and uniqueInitialEntry do not have
 274                     // to be synchronized inside doWork()
 275                     if (totalEntryCount == 0)
 276                         compressNeeded = false;
 277                     else {
 278                         // when we read/wrote the beginning of the cache file, there was a set of
 279                         // unique entries. Everything after that is essentially unknown.
 280                         // If that latter part gets disproportionately big, set compressNeeded.
 281                         int uncompressedEntryCount = totalEntryCount - uniqueInitialEntryCount;
 282                         compressNeeded = (uncompressedEntryCount * 100 / totalEntryCount > compressPercentLevel);
 283                     }
 284                 }
 285             }
 286         }
 287         catch (IOException e) {
 288             // A serious error has occurred that cannot be recovered from;
 289             // report it, and give up
 290             observer.error(e);
 291         }
 292         catch (InterruptedException e) {
 293             // should never happen, but if it does, we were idle anyway
 294             // so just return, and exit the worker thread
 295         }
 296         finally {
 297             try {
 298                 raf.close();
 299             }
 300             catch (IOException e) {
 301                 // ignore
 302             }
 303 
 304             synchronized (this) {
 305                 worker = null;
 306                 notifyAll();
 307             }
 308         }
 309     }
 310 
 311     private void doWork() throws IOException {
 312         Map<String, TestResult> tests = null;
 313         boolean rebuildCache = false;
 314 
 315         getLock();
 316 
 317         try {
 318             // if cache file exists and has content, read it all or read updates
 319             // as appropriate; if any errors occur, zap the file, so it will be rebuilt
 320             try {
 321                 if (raf.length() > 0) {
 322                     tests = readCache();
 323                 } else {
 324                     rebuildCache = true;
 325                 }
 326             }
 327             catch (Throwable e) {
 328                 // cache appears to be corrupt; empty it and rebuild it
 329                 if (DEBUG_BASIC)
 330                     Debug.println("TRC.corrupt " + e);
 331                 workDir.log(i18n, "trc.reloadFault", e);
 332                 rebuildCache = true;
 333                 raf.setLength(0);
 334             }
 335 
 336             // if we're rebuilding the cache and the VM has started to shut down,
 337             // quit rebuilding the cache and give up, as quickly as possible,
 338             // leaving the next client to rebuild the cache instead
 339             if (rebuildCache && shutdownRequested) {
 340                 testsToWrite.flush();
 341                 raf.setLength(0);
 342                 return;
 343             }
 344 
 345             // if cache is empty, rebuild it from .jtr files;
 346             // note that a valid cache with no tests has length 4
 347             if (rebuildCache) {
 348                 observer.buildingCache(rebuildCache);
 349                 tests = readJTRFiles();
 350                 observer.builtCache();
 351             }
 352 
 353             if (rebuildCache || compressRequested || raf.length() == 0) {
 354                 writeCache(tests);
 355                 // it is safe to clear the compressRequested flag because the client
 356                 // can only set it to true (not false, nor read it)
 357                 compressRequested = false;
 358             }
 359 
 360             // write any outstanding tests
 361             updateCache(tests);
 362         }
 363         finally {
 364             // if we're exiting abnormally, leave the next user to clean up
 365             // if the file is corrupt; for now, it is better to unlock the
 366             // file to say we're not using it any more
 367             releaseLock();
 368         }
 369 
 370         if (updateNeeded) {
 371             if (!shutdownRequested) {
 372                 observer.update(tests);
 373             }
 374             // it is safe to clear the fullUpdateRequested flag because the client
 375             // can only set it to true (not false, nor read it)
 376             fullUpdateRequested = false;
 377         }
 378     }
 379 
 380     private static final int MIN_TEST_READ_INTERVAL = 10000; // 10 seconds
 381     private static final int MIN_TEST_WRITE_INTERVAL = 10000; // 10 seconds
 382 
 383     private boolean isWorkAvailable(long timeLastWork) {
 384         if (compressRequested || flushRequested || fullUpdateRequested) {
 385             if (DEBUG_CHECK_WORK)
 386                 Debug.println("TRC.haveWork (request"
 387                               + (compressRequested ? ":compress" : "")
 388                               + (flushRequested ? ":flush" : "")
 389                               + (fullUpdateRequested ? ":update" : "") + ")");
 390             return true;
 391         }
 392 
 393         long now = System.currentTimeMillis();
 394 
 395         if (now - timeLastWork >= MIN_TEST_WRITE_INTERVAL && testsToWrite.size() > 0) {
 396             if (DEBUG_CHECK_WORK)
 397                 Debug.println("TRC.haveWork (" + testsToWrite.size() + " tests)");
 398             return true;
 399         }
 400 
 401         try {
 402             if (now - timeLastWork >= MIN_TEST_READ_INTERVAL && raf.length() != lastFileSize) {
 403                 if (DEBUG_CHECK_WORK)
 404                     Debug.println("TRC.haveWork (file size changed: " + raf.length() + ")");
 405                 return true;
 406             }
 407         }
 408         catch (IOException e) {
 409             // if an error occurred, we ought to let the worker thread go investigate
 410             if (DEBUG_CHECK_WORK)
 411                 Debug.println("TRC.haveWork (" + e.getMessage() + ")");
 412             return true;
 413         }
 414 
 415         return false;
 416     }
 417 
 418     //-------------------------------------------------------------------------------------
 419     //
 420     // shutdown handler code
 421 
 422     private static final int MAX_SHUTDOWN_TIME = 30000; // 30 seconds
 423 
 424     synchronized void shutdown() {
 425         if (DEBUG_BASIC)
 426             Debug.println("TRC.worker shutdown, " + testsToWrite.size() + " tests to flush");
 427 
 428         // shutdownRequested is initially false, and gets set true here;
 429         // once set true, it stays true and never goes false again, which
 430         // reduces the need for synchronized access
 431         shutdownRequested = true;
 432         if (testsToWrite.size() > 0)
 433             flushRequested = true;
 434         notifyAll();
 435 
 436         long now = System.currentTimeMillis();
 437         long end = now + MAX_SHUTDOWN_TIME;
 438         try {
 439             while (worker != null & now < end) {
 440                 if (DEBUG_SYNC)
 441                     Debug.println("TRC.shutdown waiting for worker to exit");
 442 
 443                 wait(end - now);
 444                 now = System.currentTimeMillis();
 445             }
 446 
 447             if (DEBUG_SYNC)
 448                 Debug.println("TRC.shutdown done");
 449         }
 450         catch (InterruptedException e) {
 451             // ignore
 452         }
 453 
 454         try {
 455             if (workDir != null && workDir.getTestSuite() != null) {
 456                 Logger log = workDir.getTestSuite().getLog(workDir, i18n.getString("core.log.name"));
 457                 if (log != null && log.getHandlers() != null) {
 458                     for (Handler handler : log.getHandlers()) {
 459                         if (handler instanceof WorkDirLogHandler) {
 460                             ((WorkDirLogHandler) handler).close();
 461                         }
 462                     }
 463                 }
 464             }
 465         }
 466         catch (TestSuite.NoSuchLogFault noSuchLogFault) {
 467             //nothing to do
 468         }
 469 
 470         // important to avoid memory leak !!!
 471         try {
 472             if (shutdownHandler != null) {
 473                 Runtime.getRuntime().removeShutdownHook(shutdownHandler);
 474             }
 475         }
 476         catch(IllegalStateException ex) {
 477             // it's ok if shutdown is in process now
 478         }
 479     }
 480 
 481     //-------------------------------------------------------------------------------------
 482     //
 483     // Read a set of tests from the *.jtr files in the work directory
 484 
 485     private Map<String, TestResult> readJTRFiles() {
 486         final long start = System.currentTimeMillis();
 487         Map<String, TestResult> tests = new TreeMap<>();
 488         readJTRFiles(workDir.getRoot(), tests);
 489 
 490         // these lines are all for logging benchmark info
 491         final long time = System.currentTimeMillis() - start;
 492         Logger log = null;
 493         try {
 494             log = workDir.getTestSuite().createLog(workDir, null,
 495                        i18n.getString("core.log.name"));
 496         }
 497         catch (TestSuite.DuplicateLogNameFault f) {
 498             try {
 499                 log = workDir.getTestSuite().getLog(workDir, i18n.getString("core.log.name"));
 500             }
 501             catch (TestSuite.NoSuchLogFault f2) { }
 502         }
 503 
 504         if (log != null) {
 505             Integer loadTime = new Integer((int) (time / 1000));
 506             Object[] params = new Object[]{loadTime};
 507             String output = i18n.getString("trc.log.rtime", params);
 508             log.info(output);
 509             if (DEBUG_BASIC) Debug.println(output);
 510         }
 511 
 512         return tests;
 513     }
 514 
 515     private void readJTRFiles(File dir, Map<String, TestResult> tests) {
 516         File[] entries = dir.listFiles();
 517         if (entries != null) {
 518             // monitor shutdownRequested and give up if set true;
 519             // no specific notification is passed back in this case;
 520             // it is assumed the caller will also check shutdownRequested
 521             // and act appropriately
 522             for (int i = 0; i < entries.length && !shutdownRequested; i++) {
 523                 File f = entries[i];
 524                 if (f.isDirectory())
 525                     readJTRFiles(f, tests);
 526                 else if (TestResult.isResultFile(f)) {
 527                     try {
 528                         TestResult tr = new TestResult(f);
 529                         tests.put(tr.getWorkRelativePath(), tr);
 530                     }
 531                     catch (TestResult.ResultFileNotFoundFault e) {
 532                         // hmm, should not happen, since we just read the directory
 533                         workDir.log(i18n, "trc.lostjtr", f);
 534                     }
 535                     catch (TestResult.ReloadFault e) {
 536                         // delete this jtr and continue
 537                         // should we inform TRT? perhaps via observer
 538                          workDir.log(i18n, "trc.badjtr", new Object[] {f, e.getLocalizedMessage()});
 539                         f.delete();
 540                     }
 541                 }
 542                 entries[i] = null;  // just to help GC
 543             }
 544         }
 545     }
 546 
 547     private TestResult reload(Map<String, TestResult> tests, TestResult tr) {
 548         File jtr = workDir.getFile(tr.getWorkRelativePath());
 549         try {
 550             return new TestResult(jtr);
 551         }
 552         catch (TestResult.ResultFileNotFoundFault e) {
 553             // test is presumably not run or has been purged
 554             // this notRun status will persist in cache until cache rebuilt
 555             String name = tr.getTestName();
 556             tr = new TestResult(name, workDir, Status.notRun(""));
 557             tests.put(name, tr); // in case fullUpdateRequested
 558             return tr;
 559         }
 560         catch (TestResult.ReloadFault e) {
 561             // bad .jtr, delete it
 562             workDir.log(i18n, "trc.badjtr", new Object[] {jtr, e.getLocalizedMessage()});
 563             jtr.delete();
 564             // this notRun status will persist in cache until cache rebuilt
 565             String name = tr.getTestName();
 566             tr = new TestResult(name, workDir, Status.notRun("previous results corrupted"));
 567             tests.put(name, tr); // in case fullUpdateRequested
 568             return tr;
 569         }
 570     }
 571 
 572     //-------------------------------------------------------------------------------------
 573     //
 574     // Read the cache
 575 
 576     private Map<String, TestResult> readCache()
 577         throws IOException, IllegalArgumentException
 578     {
 579         final long start = System.currentTimeMillis();
 580 
 581         if (DEBUG_WORK)
 582             Debug.println("TRC.readCache");
 583 
 584         raf.seek(0);
 585         int fileSerial = raf.readInt();
 586 
 587         if (DEBUG_WORK)
 588             Debug.println("TRC.readCache serial=" + fileSerial);
 589 
 590         if (lastFileSize == -1 || fileSerial != lastSerial
 591             || fullUpdateRequested || compressRequested) {
 592             updateNeeded = (fullUpdateRequested
 593                             || fileSerial != lastSerial
 594                             || raf.length() > lastFileSize);
 595             // read full cache
 596             lastSerial = fileSerial;
 597             totalEntryCount = 0;
 598             Map<String, TestResult> tests = readCacheEntries();
 599             uniqueInitialEntryCount = tests.size();
 600 
 601             if (DEBUG_WORK)
 602                 Debug.println("TRC.readCache read all (" + tests.size() + " tests, " + uniqueInitialEntryCount + " unique)");
 603 
 604             final long time = System.currentTimeMillis() - start;
 605             Logger log = null;
 606             try {
 607                 log = workDir.getTestSuite().createLog(workDir, null,
 608                            i18n.getString("core.log.name"));
 609             }
 610             catch (TestSuite.DuplicateLogNameFault f) {
 611                 try {
 612                     log = workDir.getTestSuite().getLog(workDir, i18n.getString("core.log.name"));
 613                 }
 614                 catch (TestSuite.NoSuchLogFault f2) { }
 615             }
 616 
 617             if (log != null) {
 618                 Integer loadTime = new Integer((int) (time / 1000));
 619                 Object[] params = new Object[]{loadTime};
 620                 String output = i18n.getString("trc.log.ptime", params);
 621                 log.info(output);
 622                 if (DEBUG_BASIC) Debug.println(output);
 623             }
 624 
 625             return tests;
 626         }
 627         else if (raf.length() > lastFileSize) {
 628             // just read updates from file
 629             raf.seek(lastFileSize);
 630             Map<String, TestResult> tests = readCacheEntries();
 631 
 632             if (DEBUG_WORK)
 633                 Debug.println("TRC.readCache read update (" + tests.size() + " tests)");
 634 
 635             updateNeeded = true;
 636             return tests;
 637         }
 638         else {
 639             // no updates available
 640             updateNeeded = false;
 641             return null;
 642         }
 643     }
 644 
 645     private Map<String, TestResult> readCacheEntries()
 646         throws IOException, IllegalArgumentException
 647     {
 648         Map<String, TestResult> tests = new TreeMap<>();
 649         while (raf.getFilePointer() < raf.length()) {
 650             String name = raf.readUTF();
 651             int status = raf.readInt();
 652             String reason = raf.readUTF();
 653             long endTime = raf.readLong();
 654             TestResult tr = new TestResult(name, workDir, new Status(status, reason), endTime);
 655             File f = tr.getFile();
 656             if (!f.exists()) {
 657                 tr.resetFile();
 658             }
 659             tests.put(tr.getWorkRelativePath(), tr);
 660             totalEntryCount++; // count all entries, including duplicates
 661         }
 662         lastFileSize = raf.length();
 663         return tests;
 664     }
 665 
 666     //-------------------------------------------------------------------------------------
 667     //
 668     // Write the cache
 669 
 670     private void writeCache(Map<String, TestResult> tests) throws IOException {
 671         if (tests == null)
 672             throw new IllegalStateException();
 673 
 674         // merge any tests in testsToWrite
 675         // testsToWrite is a thread-safe fifo, so it is safe to keep reading
 676         // it till its empty, even though some tests may even have been added
 677         // after the worker woke up
 678         TestResult tr;
 679         while ((tr = testsToWrite.remove()) != null) {
 680             // check if test is in the set we've just read
 681             String name = tr.getTestName();
 682             TestResult tr2 = tests.get(name);
 683             // if the cache file contains a conflicting entry,
 684             // reload the test from the .jtr file; otherwise, add it to the cache
 685             if (tr2 != null && !tr2.getStatus().equals(tr.getStatus()))
 686                 reload(tests, tr);
 687             else
 688                 tests.put(tr.getWorkRelativePath(), tr);
 689         }
 690 
 691         // write cache
 692         raf.seek(0);
 693         long now = System.currentTimeMillis();
 694         lastSerial = (int) ((now >> 16) + (now & 0xffff));
 695         raf.writeInt(lastSerial);
 696 
 697         for (Iterator<TestResult> iter = tests.values().iterator(); iter.hasNext(); ) {
 698             tr = iter.next();
 699             writeCacheEntry(tr);
 700         }
 701 
 702         if (DEBUG_WORK)
 703             Debug.println("TRC.writeCache write all (" + tests.size() + " tests)");
 704 
 705         raf.setLength(raf.getFilePointer());
 706         lastFileSize = raf.length();
 707         uniqueInitialEntryCount = totalEntryCount = tests.size();
 708     }
 709 
 710     private void updateCache(Map<String, TestResult> tests) throws IOException {
 711         // testsToWrite is a thread-safe fifo, so it is safe to keep reading
 712         // it till its empty, even though some tests may even have been added
 713         // after the worker woke up
 714         int debugCount = 0;
 715         raf.seek(lastFileSize);
 716         TestResult tr;
 717         while ((tr = testsToWrite.remove()) != null) {
 718             if (tests != null) {
 719                 // check if test is in the set we've just read
 720                 String name = tr.getTestName();
 721                 TestResult tr2 = tests.get(name);
 722                 if (tr2 != null) {
 723                     // cache also contains an entry for this test:
 724                     // reload from .jtr file in case of conflict
 725                     if (!tr2.getStatus().equals(tr.getStatus()))
 726                         tr = reload(tests, tr);
 727                 }
 728             }
 729             writeCacheEntry(tr);
 730             debugCount++;
 731         }
 732         if (DEBUG_WORK && debugCount > 0)
 733             Debug.println("TRC.writeCache write update (" + debugCount + " tests)");
 734 
 735         raf.setLength(raf.getFilePointer());
 736         lastFileSize = raf.length();
 737     }
 738 
 739     private void writeCacheEntry(TestResult tr) throws IOException {
 740         String name = tr.getTestName();
 741         Status status = tr.getStatus();
 742         raf.writeUTF(name);
 743         raf.writeInt(status.getType());
 744 
 745         String reason = status.getReason();
 746 
 747         if (reason == null) {
 748             reason = "";
 749         }
 750 
 751         // writeUTF() can only accept a limited string length, additionally,
 752         // in this field and in the cache, the full data is not needed
 753         if (reason.length() > MAX_REASON_LENGTH) {
 754             reason = reason.substring(0,15) +
 755                         "[...]" +
 756                  reason.substring(reason.length()-MAX_REASON_LENGTH+20);
 757         }
 758         raf.writeUTF(reason);
 759 
 760 
 761         raf.writeLong(tr.getEndTime());
 762         totalEntryCount++;
 763     }
 764 
 765     //-------------------------------------------------------------------------------------
 766     //
 767     // lock acquisition and release
 768 
 769     // lock acquisition and notification parameters
 770     private static final long INITIAL_LOCK_NOTIFY_TIME = 20000; // 20 seconds
 771     private static final long LOCK_NOTIFY_INTERVAL = 60000;     // 60 second
 772     private static final long MAX_LOCK_WAIT_TIME =
 773         Integer.getInteger("javatest.trc.timeout", 5).intValue() * 60000;
 774                                                                 // default 5 minutes
 775 
 776     // retry parameters
 777     private static final int INITIAL_RETRY_DELAY_TIME = 500;    // 0.5 second
 778     private static final int MAX_RETRY_DELAY_TIME = 10000;      // 10 seconds
 779 
 780     private void getLock() throws IOException {
 781         long start = System.currentTimeMillis();
 782         int retryDelay = INITIAL_RETRY_DELAY_TIME;
 783         long lastNotified = 0;
 784 
 785         // for JDK 1.4, should consider using raf.getChannel().tryLock()
 786         while (!lockFile.createNewFile()) {
 787             long now = System.currentTimeMillis();
 788             long timeSinceStart = now - start;
 789             if (timeSinceStart < INITIAL_LOCK_NOTIFY_TIME) {
 790                 // no need to worry, yet
 791                 continue;
 792             }
 793             else if (timeSinceStart < MAX_LOCK_WAIT_TIME) {
 794                 // slowly getting nervous: periodically notify observer
 795                 long timeSinceLastNotified = now - lastNotified;
 796                 if (lastNotified == 0
 797                     || timeSinceLastNotified > LOCK_NOTIFY_INTERVAL) {
 798                     observer.waitingForLock(timeSinceStart);
 799                     lastNotified = System.currentTimeMillis();
 800                 }
 801 
 802                 // slowly increase delay while we are waiting
 803                 if (retryDelay < MAX_RETRY_DELAY_TIME)
 804                     retryDelay = Math.min(2 * retryDelay, MAX_RETRY_DELAY_TIME);
 805             }
 806             else {
 807                 // full fledge panic: trash the lock and rebuild the cache
 808                 observer.timeoutWaitingForLock();
 809                 workDir.log(i18n, "trc.lockTimeout");
 810 
 811                 try {
 812                     if (raf != null)
 813                         raf.close();
 814                 }
 815                 catch (IOException e) {
 816                     // ignore
 817                 }
 818 
 819                 cacheFile.delete();
 820                 lockFile.delete();
 821 
 822                 raf = new RandomAccessFile(cacheFile, "rw");
 823 
 824                 // leave caller to repopulate cache
 825             }
 826 
 827             // sleep for a bit before retrying to avoid busy waiting
 828             try {
 829                 Thread.currentThread().sleep(retryDelay);
 830             }
 831             catch (InterruptedException e) {
 832                 // ignore
 833             }
 834 
 835         }
 836 
 837         observer.acquiredLock();
 838     }
 839 
 840     private void releaseLock() {
 841         // for JDK 1.4, should consider releasing the FileLock obtained from
 842         // raf.getChannel().tryLock()
 843         lockFile.delete();
 844         observer.releasedLock();
 845     }
 846 
 847     //-------------------------------------------------------------------------------------
 848 
 849     // When the work thread sleeps, it zaps the main references to observer and workDir
 850     // to the possibility that the WD and TRT might be GCed, and just retains weak references.
 851     // These weak references get revived when the worker thread has work to do.
 852     private void reviveWeakReferences() {
 853         if (workDir == null)
 854             workDir = weakWorkDir.get();
 855 
 856         if (observer == null)
 857             observer = weakObserver.get();
 858     }
 859 
 860     //-------------------------------------------------------------------------------------
 861 
 862     // general instance data
 863     private Observer observer;
 864     private WeakReference<Observer> weakObserver;
 865     private WorkDirectory workDir;
 866     private WeakReference<WorkDirectory> weakWorkDir;
 867     private File cacheFile;
 868     private File lockFile;
 869     private Thread worker;
 870     private Thread shutdownHandler;
 871 
 872     // worker thread data
 873     private RandomAccessFile raf;
 874     private int uniqueInitialEntryCount;
 875     private int totalEntryCount;
 876     private int lastSerial;
 877     private long lastFileSize;
 878     private boolean updateNeeded;
 879 
 880     // synchronized data
 881     private boolean fullUpdateRequested;
 882     private boolean compressNeeded;
 883     private boolean compressRequested;
 884     private boolean flushRequested;
 885     private boolean shutdownRequested;
 886     private Fifo<TestResult> testsToWrite = new Fifo<>();
 887 
 888     private static final String V1_FILENAME = "ResultCache.jtw";
 889     private static final String V1_LOCKNAME = V1_FILENAME + ".lck";
 890     private static final String V2_FILENAME = "ResultCache2.jtw";
 891     private static final String V2_LOCKNAME = V2_FILENAME + ".lck";
 892 
 893     // other
 894     private static I18NResourceBundle i18n = I18NResourceBundle.getBundleForClass(TestResultCache.class);
 895     private static int workerNumber; // for naming threads
 896 
 897     // maximum length of reason string written into cache
 898     // writeUTF can only write a limited length string, see writeCacheEntry()
 899     private static final int MAX_REASON_LENGTH = 256;
 900 
 901     private static int debug = Debug.getInt(TestResultCache.class);
 902     private static final boolean DEBUG_BASIC =      (debug >= 1);  // basic messages and stack trace
 903     private static final boolean DEBUG_TESTS =      (debug >= 2);  // details about tests
 904     private static final boolean DEBUG_WORK  =      (debug >= 3);  // details about work done
 905     private static final boolean DEBUG_CHECK_WORK = (debug >= 4);  // details when checking for work
 906     private static final boolean DEBUG_SYNC =       (debug >= 5);  // details about thread syncs
 907 }