ee62d16a22952da724d577af259cdeae1c6522c8
braney
  Sat Jun 15 09:06:55 2019 -0700
add logging to cache, fix a bug unmapping the wrong address

diff --git src/hg/lib/trackDbCustom.c src/hg/lib/trackDbCustom.c
index 8afd61b..1d7d0a7 100644
--- src/hg/lib/trackDbCustom.c
+++ src/hg/lib/trackDbCustom.c
@@ -13,32 +13,51 @@
 #include "hdb.h"
 #include "hui.h"
 #include "ra.h"
 #include "hash.h"
 #include "net.h"
 #include "sqlNum.h"
 #include "obscure.h"
 #include "hgMaf.h"
 #include "customTrack.h"
 #include "regexHelper.h"
 #include "fieldedTable.h"
 #include "tagRepo.h"
 #include "hex.h"
 #include <openssl/sha.h>
 
+#ifndef CACHELOG
+#define cacheLog(a,...)
+#else /* CACHELOG */
+void vaCacheLog(char *format, va_list args)
+/* Call top of warning stack to issue warning. */
+{
+fputs("cacheLog: ", stderr);
+vfprintf(stderr, format, args);
+fprintf(stderr, "\n");
+fflush(stderr);
+}
 
-/* ----------- End of AutoSQL generated code --------------------- */
+void cacheLog(char *format, ...)
+/* Issue a warning message. */
+{
+va_list args;
+va_start(args, format);
+vaCacheLog(format, args);
+va_end(args);
+}
+#endif /* CACHELOG */
 
 struct trackDb *trackDbNew()
 /* Allocate a new trackDb with just very minimal stuff filled in. */
 {
 struct trackDb *tdb;
 AllocVar(tdb);
 tdb->canPack = 2;	/* Unknown value. */
 return tdb;
 }
 
 int trackDbCmp(const void *va, const void *vb)
 /* Compare to sort based on priority; use shortLabel as secondary sort key.
  * Note: parallel code to hgTracks.c:tgCmpPriority */
 {
 const struct trackDb *a = *((struct trackDb **)va);
@@ -1658,166 +1677,195 @@
     prevTdb = newTdb;
     }
 
 return newList;
 }
 
 
 static struct trackDb *checkCache(char *string, time_t time)
 /* Check to see if this db or hub has a cached trackDb. string is either a db 
  * or a SHA1 calculated from a hubUrl. Use time to see if cache should be flushed. */
 {
 char dirName[4096];
 
 safef(dirName, sizeof dirName, "/dev/shm/trackDbCache/%s", string);
 if (!isDirectory(dirName))
+    {
+    cacheLog("abandonig cache search for %s, no directory", string);
     return NULL;
+    }
 
 // look for files named by the address they use
 struct slName *files = listDir(dirName, "*");
 char fileName[4096];
 for(; files; files = files->next)
     {
     char sharedMemoryName[4096];
     safef(sharedMemoryName, sizeof sharedMemoryName, "trackDbCache/%s/%s", string, files->name);
     safef(fileName, sizeof fileName, "/dev/shm/trackDbCache/%s/%s",  string, files->name);
+    cacheLog("checking cache file %s", fileName);
     
     struct stat statBuf;
     if (stat(fileName, &statBuf) < 0)
         {
         // if we can't stat the shared memory, let's just toss it
+        cacheLog("can't stat file %s, unlinking", fileName);
         unlink(fileName);
         continue;
         }
 
     if (statBuf.st_mtime < time)
         {
         // if the cache is older than the data, toss it
+        cacheLog("cache is older than source, unlinking");
         unlink(fileName);
         continue;
         }
 
     int oflags = O_RDWR;
     int fd = shm_open(sharedMemoryName, oflags, 0666 );
     if (fd < 0)
+        {
+        cacheLog("cannot open %s", sharedMemoryName);
         continue;
+        }
 
     unsigned long address = atoi(files->name); // the name of the file is the address it uses
     unsigned long size = fileSize(fileName);
 
     u_char *mem = (u_char *) mmap((void *)address, size, PROT_READ|PROT_WRITE, MAP_PRIVATE, fd, 0);
+    cacheLog("asked for memory %lx of size %ld, got %lx",address, size, mem);
 
     if ((unsigned long)mem == address)  // make sure we can get this address
         {
         u_char *ret = mem + lmBlockHeaderSize();
+        cacheLog("using cache memory at %lx", ret);
         return (struct trackDb *)ret;
         }
-    munmap((void *)address, size);
+    cacheLog("unmapping cache memory at %lx", mem);
+    munmap((void *)mem, size);
     close(fd);
     }
 
+cacheLog("abandonig cache search for %s", string);
 return NULL;
 }
 
 struct trackDb *trackDbCache(char *db, time_t time)
 /* Check to see if this db has a cached trackDb. */
 {
+cacheLog("checking for cache for db %s at time  %ld", db, time);
 return checkCache(db, time);
 }
 
 struct trackDb *trackDbHubCache(char *trackDbUrl, time_t time)
 {
+cacheLog("checking for cache for hub %s at time  %ld", trackDbUrl, time);
 unsigned char hash[SHA_DIGEST_LENGTH];
 SHA1((const unsigned char *)trackDbUrl, strlen(trackDbUrl), hash);
 
 char newName[(SHA_DIGEST_LENGTH + 1) * 2];
 hexBinaryString(hash,  SHA_DIGEST_LENGTH, newName, (SHA_DIGEST_LENGTH + 1) * 2);
 
 return checkCache(newName, time);
 }
 
 static void cloneTdbListToSharedMem(char *string, struct trackDb *list, unsigned long size)
 /* Allocate shared memory and clone trackDb list into it. */
 {
 int oflags=O_RDWR | O_CREAT;
 
 char dirName[4096];
 safef(dirName, sizeof dirName, "/dev/shm/trackDbCache/%s", string);
 
 if (!isDirectory(dirName))
     {
+    cacheLog("making directory %s", dirName);
     makeDir(dirName);
     chmod(dirName, 0777);
     }
 
 char sharedMemoryName[4096];
 safef(sharedMemoryName, sizeof sharedMemoryName, "trackDbCache/%s",  rTempName(string, "temp", ""));
 
 char tempFileName[4096];
 safef(tempFileName, sizeof tempFileName, "/dev/shm/%s",  sharedMemoryName);
 
 int fd = shm_open(sharedMemoryName, oflags, 0666 );
 if (fd < 0)
     {
     unlink(tempFileName);
+    cacheLog("unable to oen shared memory %s errno %d", sharedMemoryName, errno);
     return;
     }
+else
+    {
+    cacheLog("oen shared memory %s", sharedMemoryName);
+    }
 ftruncate(fd, 0);
 ftruncate(fd, size);
 
 size_t psize = getpagesize();
 unsigned long pageMask = psize - 1;
 
 // we should choose an address semi-randomly and make sure we can grab it rather than assume we can
 unsigned long address;
 unsigned long paddress;
 unsigned char *mem;
 for(address = 0x7000000; address < 0xf000000; address += 0x500000)
     {
     paddress = (address + psize - 1) & ~pageMask;
 
     mem = (u_char *) mmap((void *)address, size, PROT_READ|PROT_WRITE, MAP_SHARED, fd, 0);
+    cacheLog("asked for memory %lx of size %ld, got %lx",address, size, mem);
     if ((unsigned long)mem == address)
         break;
+    cacheLog("unmapping memory at %lx",mem);
+    munmap((void *)mem, size);
     }
 
 if (address >= 0xf000000)
     errAbort("can't get address");
 
 struct lm *lm = lmInitWMem(mem, size);
 struct hash *superHash = newHash(8);
 
 lmCloneTdbList(lm, list, NULL, superHash);
 
-unsigned long memUsed = lmUsed(lm);
+unsigned long memUsed = lmUsed(lm) + lmBlockHeaderSize();
+cacheLog("cloning tdbList using %ld bytes",memUsed);
 
 msync((void *)paddress, memUsed, MS_SYNC);
 ftruncate(fd, memUsed);
 
 // for the moment we're not unmapping these so multiple attached hubs will get
 // different addresses
 //munmap((void *)paddress, size);
 //close(fd);
 
 char fileName[4096];
 safef(fileName, sizeof fileName, "/dev/shm/trackDbCache/%s/%ld",  string, paddress);
 
+cacheLog("renaming %s to %s", tempFileName, fileName);
 mustRename(tempFileName, fileName);
 }
 
 void trackDbCloneTdbListToSharedMem(char *db, struct trackDb *list, unsigned long size)
-/* Allocate shared memory and clone trackDb list into it. */
+/* For this native db, allocate shared memory and clone trackDb list into it. */
 {
+cacheLog("cloning memory for db %s %ld", db, size);
 cloneTdbListToSharedMem(db, list, size);
 }
 
 void trackDbHubCloneTdbListToSharedMem(char *trackDbUrl, struct trackDb *list, unsigned long size)
+/* For this hub, Allocate shared memory and clone trackDb list into it. */
 {
+cacheLog("cloning memory for hub %s %ld", trackDbUrl, size);
 unsigned char hash[SHA_DIGEST_LENGTH];
 SHA1((const unsigned char *)trackDbUrl, strlen(trackDbUrl), hash);
 
 char newName[(SHA_DIGEST_LENGTH + 1) * 2];
 hexBinaryString(hash,  SHA_DIGEST_LENGTH, newName, (SHA_DIGEST_LENGTH + 1) * 2);
 
 cloneTdbListToSharedMem(newName, list, size);
 }