[xiph-commits] r15219 - in trunk/cdparanoia: . paranoia

xiphmont at svn.xiph.org xiphmont at svn.xiph.org
Sat Aug 30 01:13:12 PDT 2008


Author: xiphmont
Date: 2008-08-30 01:13:11 -0700 (Sat, 30 Aug 2008)
New Revision: 15219

Modified:
   trunk/cdparanoia/Makefile.in
   trunk/cdparanoia/main.c
   trunk/cdparanoia/paranoia/Makefile.in
   trunk/cdparanoia/paranoia/cachetest.c
   trunk/cdparanoia/paranoia/paranoia.c
Log:
Get more cache testing in SVN



Modified: trunk/cdparanoia/Makefile.in
===================================================================
--- trunk/cdparanoia/Makefile.in	2008-08-29 13:34:42 UTC (rev 15218)
+++ trunk/cdparanoia/Makefile.in	2008-08-30 08:13:11 UTC (rev 15219)
@@ -25,7 +25,7 @@
 LIBDIR=@libdir@
 PWD = $(shell pwd)
 
-OFILES = main.o report.o header.o buffering_write.o cachetest.o
+OFILES = main.o report.o header.o buffering_write.o
 
 export STATIC 
 export VERSION

Modified: trunk/cdparanoia/main.c
===================================================================
--- trunk/cdparanoia/main.c	2008-08-29 13:34:42 UTC (rev 15218)
+++ trunk/cdparanoia/main.c	2008-08-30 08:13:11 UTC (rev 15219)
@@ -1041,7 +1041,7 @@
     int warn=paranoia_analyze_verify(d, stderr, reportfile);
     
     if(warn==0){
-      reportC("\nDrive tests OK with Paranoia.\n");
+      reportC("\nDrive tests OK with Paranoia.\n\n");
       return 0;
     }
 

Modified: trunk/cdparanoia/paranoia/Makefile.in
===================================================================
--- trunk/cdparanoia/paranoia/Makefile.in	2008-08-29 13:34:42 UTC (rev 15218)
+++ trunk/cdparanoia/paranoia/Makefile.in	2008-08-30 08:13:11 UTC (rev 15219)
@@ -18,7 +18,7 @@
 RANLIB=@RANLIB@
 CPPFLAGS+=-D_REENTRANT
 
-OFILES = paranoia.o p_block.o overlap.o gap.o isort.o
+OFILES = paranoia.o p_block.o overlap.o gap.o isort.o cachetest.o
 #TFILES = isort.t gap.t p_block.t paranoia.t
 
 LIBS = ../interface/libcdda_interface.a -lm

Modified: trunk/cdparanoia/paranoia/cachetest.c
===================================================================
--- trunk/cdparanoia/paranoia/cachetest.c	2008-08-29 13:34:42 UTC (rev 15218)
+++ trunk/cdparanoia/paranoia/cachetest.c	2008-08-30 08:13:11 UTC (rev 15219)
@@ -29,6 +29,12 @@
 #define printC(...) {if(progress){fprintf(progress, __VA_ARGS__);}}
 #define logC(...) {if(log){fprintf(log, __VA_ARGS__);}}
 
+static float ms_per_sector_at(int lba, float *waypoint){
+  int waypos = (lba+44999)/45000;
+  if(waypos<0)waypos=0;
+  while(waypos>=0 && waypoint[waypos]==-1)waypoint--;
+  return waypoint[waypos];
+}
 
 int paranoia_analyze_verify(cdrom_drive *d, FILE *progress, FILE *log){
 
@@ -56,7 +62,7 @@
      we're consistently hitting latency on the same sector during
      initial collection, may need to move past it. */
 
-  int i,ret;
+  int i,j,ret;
   int firstsector=-1;
   int lastsector=-1;
   int firsttest=-1;
@@ -65,6 +71,13 @@
   float median;
   int offset;
   int warn=0;
+  int current=1000;
+  int hi=15000;
+  int cachesize;
+  int readahead;
+  int rollbehind;
+  int cachegran;
+  float waypoint[10]={-1,-1,-1,-1, -1,-1,-1,-1, -1,-1};
 
   /* set up a default pessimal take on drive behavior */
   //d->private->cache_backseekflush=0;
@@ -98,7 +111,6 @@
      eyes.  Take readings ten minutes apart (45000 sectors) and at end of disk. */
   {
     int x;
-    int current=1000;
     int latency[current];
     int sectors[current];
     double sum;
@@ -166,7 +178,6 @@
 	double mean = sum/(float)(current-1);
 	double stddev = sqrt( (sumsq/(float)(current-1) - mean*mean));
 	double upper= mean+((isnan(stddev) || stddev*2<1.)?1.:stddev*2);
-	int j;
 	
 	mean=0;
 	sofar=0;
@@ -179,6 +190,12 @@
 	}
 	mean/=sofar;
 	
+	{
+	  int waypos = offset/45000;
+	  if(waypoint[waypos]==-1 || waypoint[waypos]>mean)
+	    waypoint[waypos]=mean;
+	}
+
 	printC("%4dms seek, %.2fms/sec read [%.1fx]",latency[0],mean,1000./75./mean);
 	logC("\n\tInitial seek latency (%d sectors): %dms",current,latency[0]);
 	logC("\n\tAverage read latency: %.2fms/sector (raw speed: %.1fx)",mean,1000./75./mean);
@@ -186,12 +203,12 @@
 
 	sofar=mean*current;
 	if(!iterating){
-	  if(-sofar<best){
-	    best=-sofar;
+	  if(best==0 || sofar*1.01<best){
+	    best= sofar;
 	    bestcount=0;
 	  }else{
 	    bestcount+=sofar;
-	    if(bestcount>sofar && bestcount>2000)
+	    if(bestcount>sofar && bestcount>4000)
 	      iterating=1;
 	  }
 	}
@@ -214,92 +231,272 @@
   /* search on cache size; cache hits are fast, seeks are not, so a
      linear search through cache hits up to a miss are faster than a
      bisection */
-
-  int hi=15000;
-  int current=0;
-  int under=1;
-  offset = firstsector;
-
-  while(current <= hi && under){
-    int i,j;
-    under=0;
-    current++;
-
-    printC("\r");
-    reportC("\tFast search for approximate cache size... %d sectors            ",current-1);
-    logC("\n");
-
-    for(i=0;i<15 && !under;i++){
-      for(j=0;;j++){
-	int ret1,ret2;
-	if(i>=5){
-	  int sofar=0;
+  {
+    int under=1;
+    current=0;
+    offset = firstsector+10;
+    
+    while(current <= hi && under){
+      int i,j;
+      under=0;
+      current++;
+      
+      printC("\r");
+      reportC("\tFast search for approximate cache size... %d sectors            ",current-1);
+      logC("\n");
+      
+      for(i=0;i<15 && !under;i++){
+	for(j=0;;j++){
+	  int ret1,ret2;
+	  if(i>=5){
+	    int sofar=0;
+	    
+	    if(i==5){
+	      printC("\r");
+	      reportC("\tSlow verify for approximate cache size... %d sectors",current-1);
+	      logC("\n");
+	      
+	      logC("\tAttempting to reduce read speed to 1x... ");
+	      if(cdda_speed_set(d,1)){
+		logC("failed.\n");
+	      }else{
+		logC("drive said OK\n");
+	      }
+	    }
+	    printC(".");
+	    logC("\t\t>>> ");
+	    
+	    while(sofar<current){
+	      ret1 = cdda_read(d,NULL,offset+sofar,current-sofar);
+	      logC("slow_read=%d:%d ",ret1,cdda_milliseconds(d));
+	      if(ret1<=0)break;
+	      sofar+=ret1;
+	    }
+	  }else{
+	    ret1 = cdda_read(d,NULL,offset+current-1,1);
+	    logC("\t\t>>> fast_read=%d:%d ",ret1,cdda_milliseconds(d));
+	  }
+	  ret2 = cdda_read(d,NULL,offset,1);
+	  logC("seek_read=%d:%d\n",ret2,cdda_milliseconds(d));
 	  
-	  if(i==5){
-	    printC("\r");
-	    reportC("\tSlow verify for approximate cache size... %d sectors",current-1);
-	    logC("\n");
-
-	    logC("\tAttempting to reduce read speed to 1x... ");
-	    if(cdda_speed_set(d,1)){
-	      logC("failed.\n");
+	  if(ret1<=0 || ret2<=0){
+	    offset+=current+100;
+	    if(j==10 || offset+current>lastsector){
+	      reportC("\n\tToo many read errors while performing drive cache checks;"
+		      "\n\t  aborting test.\n\n");
+	      return(-1);
+	    }
+	    reportC("\n\tRead error while performing drive cache checks;"
+		    "\n\t  choosing new offset and trying again.\n");
+	  }else{
+	    if(cdda_milliseconds(d)==-1){
+	      reportC("\n\tTiming error while performing drive cache checks; aborting test.\n");
+	      return(-1);
 	    }else{
-	      logC("drive said OK\n");
+	      if(cdda_milliseconds(d)<9)under=1;
+	      break;
 	    }
 	  }
-	  printC(".");
-	  logC("\t\t>>> ");
-
-	  while(sofar<current){
-	    ret1 = cdda_read(d,NULL,offset+sofar,current-sofar);
-	    logC("slow_read=%d:%d ",ret1,cdda_milliseconds(d));
-	    if(ret1<=0)break;
-	    sofar+=ret1;
-	  }
-	}else{
-	  ret1 = cdda_read(d,NULL,offset+current-1,1);
-	  logC("\t\t>>> fast_read=%d:%d ",ret1,cdda_milliseconds(d));
 	}
-	ret2 = cdda_read(d,NULL,offset,1);
-	logC("seek_read=%d:%d\n",ret2,cdda_milliseconds(d));
-	
-	if(ret1<=0 || ret2<=0){
-	  offset+=current+100;
-	  if(j==10 || offset+current>lastsector){
-	    reportC("\n\tToo many read errors while performing drive cache checks;"
-		    "\n\t  aborting test.\n\n");
-	    return(-1);
-	  }
-	  reportC("\n\tRead error while performing drive cache checks;"
-		  "\n\t  choosing new offset and trying again.\n");
-	}else{
-	  if(cdda_milliseconds(d)==-1){
-	    reportC("\n\tTiming error while performing drive cache checks; aborting test.\n");
-	    return(-1);
-	  }else{
-	    if(cdda_milliseconds(d)<9)under=1;
-	    break;
-	  }
-	}
       }
-    }
-  } 
+    } 
+  }
+  cachesize=current-1;
 
   printC("\r");
-  if(current==hi){
+  if(cachesize==hi){
     reportC("\tWARNING: Cannot determine drive cache size or behavior!          \n");
     return 1;
-  }else if(current>1){
-    reportC("\tApproximate random access cache size: %d sectors                 \n",current-1);
+  }else if(cachesize){
+    reportC("\tApproximate random access cache size: %d sector(s)               \n",cachesize);
   }else{
     reportC("\tDrive does not cache nonlinear access                            \n");
     return 0;
   }
    
+  /* The readahead cache size ascertained above is likely qualified by
+     background 'rollahead'; that is, the drive's readahead process is
+     often working ahead of our actual linear reads, and if reads stop
+     or are interrupted, readahead continues and overflows the cache.
+     It is also the case that the cache size we determined above is
+     slightly too low because readahead is probably always working
+     ahead of reads. 
+
+     Determine the rollahead size a few ways (which may disagree:
+     1) Read number of sectors equal to cache size; pause; read backward until seek
+     2) Read sectors equal to cache-rollahead; verify reading back to beginning does not seek 
+     3) Read sectors equal to cache; pause; read ahead until seek delay
+  */
+
+  {
+    int under=1;
+    readahead=0;
+    
+    while(under && readahead<hi){
+      under=0;
+      readahead++;
+      printC("\r");
+      reportC("\tTesting background readahead past read cursor... %d",readahead-1);
+      
+      for(i=0;i<10;i++){
+	int sofar=0,ret,retry=0;
+	printC(".          \b\b\b\b\b\b\b\b\b\b");
+	logC("\n\t\t%d >>> ",i);
+	
+	while(sofar<cachesize){
+	  ret = cdda_read(d,NULL,offset+sofar,1);
+	  if(ret<=0)goto error;
+	  logC("%d:%d ",ret,cdda_milliseconds(d));
+
+	  /* some drives can lose sync and perform an internal resync,
+	     which can also cause readahead to restart.  If we see
+	     seek-like delays during the initial cahe load, retry the
+	     preload */
+
+	  sofar+=ret;
+	}
+	
+	/* Pause 5x what we'd predict is needed to let the readahead process work. */
+	{
+	  int usec=ms_per_sector_at(offset,waypoint)*(cachesize+readahead)*(2+i)*1000;
+	  logC("sleep=%dus ",usec);
+	  usleep(usec);
+	}
+	
+	/* seek to offset+cachesize+readahead */
+	ret = cdda_read(d,NULL,offset+cachesize+readahead-1,1);
+	if(ret<=0)break;
+	logC("ahead=%d:%d\n",cachesize+readahead-1,cdda_milliseconds(d));
+	if(cdda_milliseconds(d)<9){
+	  under=1;
+	  break;
+	}
+      }
+    }
+  }
+  readahead--;
+  logC("\n");
+  printC("\r");
+  if(readahead==0){
+    reportC("\tDrive does not read ahead past read cursor (very strange)  \n");
+  }else{
+    reportC("\tDrive readahead past read cursor: %d sector(s)             \n",readahead);
+  }
+  
+  reportC("\tTesting cache tail cursor");
+  rollbehind=cachesize;
+  
+  for(i=0;i<10 && rollbehind;i++){
+    int sofar=0,ret,retry=0;
+    logC("\n\t\t>>> ");
+    printC(".");
+    while(sofar<cachesize){
+      ret = cdda_read(d,NULL,offset+sofar,cachesize-sofar);
+      if(ret<=0)goto error;
+      logC("%d:%d ",ret,cdda_milliseconds(d));
+      sofar+=ret;
+    }
+    
+    /* Pause 5x what we'd predict is needed to read cachesize more sectors to let the readahead process work. */
+    {
+      int usec=ms_per_sector_at(offset+cachesize,waypoint)*cachesize*5000;
+      logC("\n\t\tsleeping %d microseconds",usec);
+      usleep(usec);
+    }
+    
+    /* read backwards until we seek */
+    logC("\n\t\t<<< ");
+    sofar=rollbehind;
+    while(sofar>0){
+      sofar--;
+      ret = cdda_read(d,NULL,offset+sofar,1);
+      if(ret<=0)break;
+      logC("%d:%d ",sofar,cdda_milliseconds(d));
+      if(cdda_milliseconds(d)>8){
+	rollbehind=sofar+1;
+	break;
+      }
+      rollbehind=sofar;
+    }
+  error:
+    if(ret<=0){
+      offset+=cachesize;
+      retry++;
+      if(retry>10 || offset+cachesize>lastsector){
+	reportC("\n\tToo many read errors while performing drive cache checks;"
+		"\n\t  aborting test.\n\n");
+	return(-1);
+      }
+      reportC("\n\tRead error while performing drive cache checks;"
+	      "\n\t  choosing new offset and trying again.\n");
+      continue;
+    }
+  }
+  
+  logC("\n");
+  printC("\r");
+  if(rollbehind==0){
+    reportC("\tCache tail cursor tied to read cursor                      \n");
+  }else{
+    reportC("\tCache tail rollbehind: %d sector(s)                        \n",rollbehind);
+  }
+  
+  reportC("\tTesting granularity of cache tail");
+  cachegran=cachesize+1;
+  
+  for(i=0;i<10 && cachegran;i++){
+    int sofar=0,ret,retry=0;
+    logC("\n\t\t>>> ");
+    printC(".");
+    while(sofar<cachesize+1){
+      ret = cdda_read(d,NULL,offset+sofar,cachesize-sofar+1);
+      if(ret<=0)goto error2;
+      logC("%d:%d ",ret,cdda_milliseconds(d));
+      sofar+=ret;
+    }
+    
+    /* Pause 5x what we'd predict is needed to read cachesize more sectors to let the readahead process work. */
+    {
+      int usec=ms_per_sector_at(offset+cachesize,waypoint)*cachesize*5000;
+      logC("\n\t\tsleeping %d microseconds",usec);
+      usleep(usec);
+    }
+    
+    /* read backwards until we seek */
+    logC("\n\t\t<<< ");
+    sofar=cachegran;
+    while(sofar>1){
+      sofar--;
+      ret = cdda_read(d,NULL,offset+sofar,1);
+      if(ret<=0)break;
+      logC("%d:%d ",sofar,cdda_milliseconds(d));
+      if(cdda_milliseconds(d)>8) break;
+    }
+    cachegran=sofar;
+  error2:
+    if(ret<=0){
+      offset+=cachesize;
+      retry++;
+      if(retry>10 || offset+cachesize>lastsector){
+	reportC("\n\tToo many read errors while performing drive cache checks;"
+		"\n\t  aborting test.\n\n");
+	return(-1);
+      }
+      reportC("\n\tRead error while performing drive cache checks;"
+	      "\n\t  choosing new offset and trying again.\n");
+      continue;
+    }
+  }
+  
+  logC("\n");
+  printC("\r");
+  reportC("\tCache tail granularity: %d sector(s)                      \n",cachegran);
+
+
   /* this drive caches; Determine if the detailed caching behavior fits our model. */
 
   /* does the readahead cache exceed the maximum Paranoia currently expects? */
-  if(current-1 > CACHEMODEL_SECTORS){
+  if(cachesize > CACHEMODEL_SECTORS){
     reportC("\nWARNING: This drive appears to be caching more sectors of\n"
 	    "           readahead than Paranoia can currently handle!\n");
     warn=1;
@@ -310,9 +507,10 @@
      cache is being tracked as multiple areas that are treated
      differently if non-contiguous.... */
   {
-    int seekoff = current*3;
-    reportC("\nVerifying that readahead cache is contiguous");
-    under=0;
+    int seekoff = cachesize*3;
+    int under=0;
+    reportC("\nVerifying that readahead cache is contiguous...\n");
+    printC("\ttesting");
   
     for(i=0;i<30 && !under;i++){
       printC(".");
@@ -327,12 +525,12 @@
 	
 
 	ret1 = cdda_read(d,NULL,offset+seekoff,1);
-	logC("\t\t>>> %d:%d ",offset+current,cdda_milliseconds(d));
+	logC("\t\t>>> %d:%d ",offset+seekoff,cdda_milliseconds(d));
 	ret2 = cdda_read(d,NULL,offset,1);
-	logC("%d:%d\n",offset,cdda_milliseconds(d));
+	logC("seek_read:%d\n",cdda_milliseconds(d));
 	
 	if(ret1<=0 || ret2<=0){
-	  offset+=current+100;
+	  offset+=cachesize+100;
 	  if(j==10){
 	    reportC("\n\tToo many read errors while performing drive cache checks;"
 		    "\n\t  aborting test.\n\n");
@@ -351,19 +549,39 @@
 	}
       }
     }
+    printC("\r");
     if(under){
-      reportC("\nWARNING: Drive cache does not appear to be contiguous!\n");
+      reportC("WARNING: Drive cache does not appear to be contiguous!\n");
       warn=1;
     }else{
-      reportC("\n\tdone.  Drive cache tests as contiguous.\n");
+      reportC("\tDrive cache tests as contiguous.                \n");
     }
   }
 
-  /* does a read beyond shift the cache or dump it? */
-
   /* Verify that a read that begins before the cached readahead dumps
      the entire readahead cache */
 
+  /* This is tricky because we can't simply read a one sector
+     back seek, then rely on timing/seeking of subsequent sectors; the
+     drive may well not seek ahead if reading linearly would be faster
+     (and it often will be), and simply reading haead after the seek
+     and watching timing will be inaccurate because the drive may roll
+     some readahead into the initial seek before returning the first
+     block. */
+
+  /* we will need to use the timing of reading from media in one form
+     or another and thus need to guard against slow bus transfer times
+     [eg, no DMA] swamping the actual read time from media. */
+
+  /* sample cache access for ten realtime seconds. */
+  //{
+    //int cachems;
+
+    //reportC("\nVerifying that seeking before cache dumps readahead...");
+    //reportC("\n\tSampling cache timing... ");
+  //}
+
+
   /* Check to see that cdda_clear_cache clears the specified cache area */
 
   /* Does cdda_clear_cache result in noncontiguous cache areas? */

Modified: trunk/cdparanoia/paranoia/paranoia.c
===================================================================
--- trunk/cdparanoia/paranoia/paranoia.c	2008-08-29 13:34:42 UTC (rev 15218)
+++ trunk/cdparanoia/paranoia/paranoia.c	2008-08-30 08:13:11 UTC (rev 15219)
@@ -76,6 +76,7 @@
 #include <math.h>
 #include "../interface/cdda_interface.h"
 #include "../interface/smallft.h"
+#include "../version.h"
 #include "p_block.h"
 #include "cdda_paranoia.h"
 #include "overlap.h"



More information about the commits mailing list