[xiph-commits] r15201 - in trunk/cdparanoia: . interface
xiphmont at svn.xiph.org
xiphmont at svn.xiph.org
Tue Aug 26 00:24:37 PDT 2008
Author: xiphmont
Date: 2008-08-26 00:24:36 -0700 (Tue, 26 Aug 2008)
New Revision: 15201
Modified:
trunk/cdparanoia/cachetest.c
trunk/cdparanoia/interface/scsi_interface.c
trunk/cdparanoia/main.c
trunk/cdparanoia/report.c
trunk/cdparanoia/report.h
Log:
cdparanoia now explicitly sets max CDROM speed unless told to select
some other speed.
Add in beginnings of cache test as part of -A; add related options to
make the option useful (specifically -L).
Modified: trunk/cdparanoia/cachetest.c
===================================================================
--- trunk/cdparanoia/cachetest.c 2008-08-25 20:39:42 UTC (rev 15200)
+++ trunk/cdparanoia/cachetest.c 2008-08-26 07:24:36 UTC (rev 15201)
@@ -29,6 +29,7 @@
#include <string.h>
#include <stdio.h>
+#include <math.h>
#include "interface/cdda_interface.h"
#include "report.h"
#include "cachetest.h"
@@ -64,7 +65,6 @@
int lastsector=-1;
int firsttest=-1;
int lasttest=-1;
- char buffer[80];
int max_retries=20;
float median;
int offset;
@@ -73,7 +73,7 @@
//d->private->cache_backseekflush=0;
//d->private->cache_sectors=1200;
- reportC("\nChecking drive timing behavior...");
+ reportC("\n=================== Checking drive cache/timing behavior ===================\n");
/* find the longest stretch of available audio data */
@@ -98,148 +98,169 @@
}
/* Dump some initial timing data to give a little context for human
- eyes. This isn't actually used in timing anywhere. */
- if(verbose){
+ eyes. Take readings ten minutes apart (45000 sectors) and at end of disk. */
+ {
int x;
- int current=300;
- int acc=0;
- int prev=0;
+ int current=1000;
+ int latency[current];
+ int sectors[current];
+ double sum;
+ double sumsq;
+ int sofar;
+ double best=0;
+ int bestcount=0;
- offset = firstsector;
+ offset = lastsector-firstsector-current-1;
- if((ret=cdda_read(d,NULL,offset+current+1,1))<0){
- /* media error! grr! retry elsewhere */
- reportC("\n\tWARNING: media error; picking new location and trying again.");
- continue;
- }
+ reportC("\nSeek/read timing:\n");
- reportC("\n\tSector timings (ms):\n\t");
+ while(offset>=firstsector){
+ int m = offset/4500;
+ int s = (offset-m*4500)/75;
+ int f = offset-m*4500-s*75;
+ if(bestcount==10){
+ reportC("\n");
+ }else{
+ printC("\r");
+ logC("\n");
+ }
+ reportC("\t[%02d:%02d.%02d]: ",m,s,f);
+ sum=0;
+ sumsq=0;
- for(i=0;i<current;i++){
- if(cdda_read(d,NULL,offset+i,1)<0){
+ /* initial seek to put at at a small offset past end of upcoming reads */
+ if((ret=cdda_read(d,NULL,offset+current+1,1))<0){
+ /* media error! grr! retry elsewhere */
+ if(ret==-404)return -1;
+ reportC("\n\tWARNING: media error during setup; continuing at next offset...");
+ goto next;
+ }
+
+ logC("\n");
+
+ for(i=0,sofar=0;sofar<current;i++){
+ int toread = (i==0?1:current-sofar);
+ int ret;
+ /* first read should also trigger a short seek; one sector so seek duration dominates */
+ if((ret=cdda_read(d,NULL,offset+sofar,toread))<=0){
/* media error! grr! retry elsewhere */
- reportC("\n\tWARNING: media error; picking new location and trying again.");
- break;
+ if(ret==-404)return -1;
+ reportC("\n\tWARNING: media error during read; continuing at next offset...");
+ goto next;
}
+
x = cdda_milliseconds(d);
if(x>9999)x=9999;
if(x<0)x=0;
- reportC("%d ",x);
+ logC("%d:%d ",ret,x);
- histogram[x]++;
latency[i]=x;
- }
- if(i<current){
- offset-=current+1;
- continue;
- }
-
- for(i=0;i<10000;i++){
- prev=acc;
- acc+=histogram[i];
- if(acc>current/2){
- reportC("\n\tSurrounding histogram: ");
- if(i)
- reportC("%dms:%d ",i-1,acc-histogram[i]);
-
- reportC("%dms:%d ",i,acc);
- if(i<999)
- reportC("%dms:%d ",i+1,acc+histogram[i+1]);
- reportC("\n");
- break;
+ sectors[i]=ret;
+ sofar+=ret;
+ if(i){
+ sum+=x;
+ sumsq+= x*x /(float)ret;
}
}
-
- median = (i*(acc-prev) + (i-1)*prev)/(float)acc;
- reportC("\n\tsmall seek latency (%d sectors): %d ms",current,latency[0]);
- reportC("\n\tmedian read latency per sector: %.1f ms",median);
+ /* ignore upper outliers; we may have gotten random bursts of latency */
+ {
+ double mean = sum/(float)(current-1);
+ double stddev = sqrt( (sumsq/(float)(current-1) - mean*mean));
+ double upper= mean+((isnan(stddev) || stddev<1.)?1.:stddev);
+ int j;
+
+ mean=0;
+ sofar=0;
+ for(j=1;j<i;j++){
+ double per = latency[j]/(double)sectors[j];
+ if(per<=upper){
+ mean+=latency[j];
+ sofar+=sectors[j];
+ }
+ }
+ mean/=sofar;
+
+ 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);
+ logC("\n\tRead latency standard deviation: %.2fms/sector",stddev);
- /* verify slow spinup did not compromise median */
- for(i=1;i<current;i++)
- if(latency[i]>latency[i-1] || latency[i]<=(median+1.))break;
- if(i>5){
- reportC("\n\tDrive appears to spin up slowly... retrying...");
- offset-=current+1;
- continue;
+ if(bestcount<10){
+ if(1./mean>best){
+ best=1./mean;
+ bestcount=0;
+ }else
+ bestcount++;
+ }
}
+ next:
- /* verify against spurious latency; any additional 5x blocks that
- are not continuous with read start */
- acc=0;
- if(median<.6)median=.6;
- for(i=5;i<current;i++)
- if(latency[i]>median*10)acc++;
-
- if(acc){
- report("\n\tWARNING: Read timing displayed bursts of unexpected"
- "\n\tlatency; retrying for a clean read.\n");
- continue;
- }
-
- break;
- }
-
- if(offset<firstsector){
- report("\n500: Unable to find sufficiently large area of"
- "\n\tgood media to perform timing tests. Aborting.\n");
- return -500;
- }
- if(retry==max_retries){
- report("\n500: Too many retries; aborting analysis.\n");
- return -500;
- }
- }
-
- /* look to see if drive is caching at all; read first sector N
- times, if any reads are near or under the median latency, we're
- caching */
- {
- for(i=0;i<max_retries;i++){
- if(d->read_audio(d,NULL,offset,1)==1){
- if(cdda_milliseconds(d)<median*10) break;
-
+ if(bestcount==10){
+ offset = (offset-firstsector+44999)/45000*45000+firstsector;
+ offset-=45000;
+ printC(" ");
}else{
- /* error handling */
+ offset--;
+ printC(" spinning up...");
}
}
-
- if(i<max_retries){
- reportC("\n\tCaching test result: DRIVE IS CACHING (bad)\n");
- }else{
- reportC("\n\tCaching test result: Drive is not caching (good)\n");
- return 0;
- }
}
-
-
-
-
-
-
+ reportC("\n\nAnalyzing readahead cache access...\n");
+
/* 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 lo=1;
int hi=15000;
- int current=lo;
+ int current=0;
int under=1;
- offset = firstsector;
+ offset = firstsector+1000;
- reportC("\n");
-
while(current <= hi && under){
int i,j;
under=0;
+ current++;
- reportC("\r\tInitial fast search for cache size... %d",current-1);
+ printC("\r");
+ reportC("\tFast search for approximate cache size... %d sectors ",current-1);
+ logC("\n");
- for(i=0;i<10 && !under;i++){
- for(j=0;;j++){
- int ret1 = cdda_read(d,NULL,offset+current-1,1);
- int ret2 = cdda_read(d,NULL,offset,1);
+ 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(ret1<=0 || ret2<=0){
if(j==2){
reportC("\n\tRead error while performing drive cache checks; aborting test.\n");
@@ -252,19 +273,35 @@
return(-1);
}
}else{
- if(cdda_milliseconds(d)<10)under=1;
+ if(cdda_milliseconds(d)<9)under=1;
break;
}
}
}
}
- current++;
}
+ printC("\r");
+ if(current>1){
+ reportC("\tApproximate random access cache size: %d sectors \n",current-1);
+ }else{
+ reportC("\tDrive does not cache nonlinear access \n");
+ return 0;
+ }
+
+ /* this drive caches; Determine if the detailed caching behavior fits our model. */
+ /* does the readahead cache exceed the maximum Paranoia currently expects? */
-
+ /* Verify that a read that begins before the cached readahead dumps
+ the entire readahead cache */
+ /* Verify that reads that begin after the apparently cached
+ readahead either dump the cache *or* cause the cached area to
+ shift later in one contiguous piece */
+
+ /* Check to see that cdda_clear_cache clears the specified cache area */
+
/* XXXXXX IN PROGRESS */
reportC("\n");
return 0;
Modified: trunk/cdparanoia/interface/scsi_interface.c
===================================================================
--- trunk/cdparanoia/interface/scsi_interface.c 2008-08-25 20:39:42 UTC (rev 15200)
+++ trunk/cdparanoia/interface/scsi_interface.c 2008-08-26 07:24:36 UTC (rev 15201)
@@ -792,8 +792,6 @@
}
static int scsi_set_speed (cdrom_drive *d, int speed){
- int ret;
- char b[80];
unsigned char cmd[12]={0xBB, 0, 0, 0, 0xff, 0xff, 0, 0, 0, 0};
unsigned char sense[SG_MAX_SENSE];
@@ -804,13 +802,10 @@
cmd[2] = (speed >> 8) & 0xFF;
cmd[3] = (speed) & 0xFF;
return handle_scsi_cmd(d,cmd,12,0,0,0,0,sense);
-
}
/* 'abuse' the set read ahead into manipulating the cache */
static int mmc_cache_clear (cdrom_drive *d, int begin, int sectors){
- int ret;
- char b[80];
unsigned char cmd[12]={0xA7, 0, 0, 0, 0, 0, 0, 0, 0, 0};
unsigned char sense[SG_MAX_SENSE];
int end=begin+sectors;
Modified: trunk/cdparanoia/main.c
===================================================================
--- trunk/cdparanoia/main.c 2008-08-25 20:39:42 UTC (rev 15200)
+++ trunk/cdparanoia/main.c 2008-08-26 07:24:36 UTC (rev 15201)
@@ -196,7 +196,7 @@
(int)(audiolen%75));
report(buffer);
}
- report("");
+ report(" ");
}
static void usage(FILE *f){
@@ -212,11 +212,20 @@
" cdparanoia [options] <span> [outfile]\n\n"
"OPTIONS:\n"
+" -A --analyze-drive : run and log a complete analysis of drive\n"
+" caching, timing and reading behavior;\n"
+" verifies that cdparanoia is correctly\n"
+" modelling a sprcific drive's cache and\n"
+" read behavior. Implies -vQL\n\n"
" -v --verbose : extra verbose operation\n"
" -q --quiet : quiet operation\n"
" -e --stderr-progress : force output of progress information to\n"
" stderr (for wrapper scripts)\n"
-" -l --log-summary <file> : save result summary to file\n"
+" -l --log-summary [<file>] : save result summary to file, default\n"
+" filename cdparanoia.log\n"
+" -L --log-debug [<file>] : save detailed device autosense and\n"
+" debugging output to file, default\n"
+" filename cdparanoia.log\n"
" -V --version : print version info and quit\n"
" -Q --query : autosense drive, query disc and quit\n"
" -B --batch : 'batch' mode (saves each track to a\n"
@@ -247,7 +256,8 @@
" -g --force-generic-device <dev> : use specified generic scsi device and\n"
" force use of the old SG kernel\n"
" interface. -g cannot be used with -k.\n"
-" -S --force-read-speed <n> : read from device at specified speed\n"
+" -S --force-read-speed <n> : read from device at specified speed; -1\n"
+" indicates full speed.\n"
" -t --toc-offset <n> : Add <n> sectors to the values reported\n"
" when addressing tracks. May be negative\n"
" -T --toc-bias : Assume that the beginning offset of \n"
@@ -263,11 +273,7 @@
" retries without progress.\n"
" -Z --disable-paranoia : disable all paranoia checking\n"
" -Y --disable-extra-paranoia : only do cdda2wav-style overlap checking\n"
-" -X --abort-on-skip : abort on imperfect reads/skips\n"
-" -U --cache-test : run a complete analysis of drive caching\n"
-" behavior; verifies that cdparanoia is\n"
-" correctly modelling a sprcific drive's\n"
-" cache behavior.\n\n"
+" -X --abort-on-skip : abort on imperfect reads/skips\n\n"
"OUTPUT SMILIES:\n"
" :-) Normal operation, low/no jitter\n"
@@ -584,7 +590,7 @@
memset(dispcache,' ',graph);
}
-const char *optstring = "escCn:o:O:d:g:k:S:prRwafvqVQhZz::YXWBi:Tt:l:U";
+const char *optstring = "escCn:o:O:d:g:k:S:prRwafvqVQhZz::YXWBi:Tt:l::L::A";
struct option options [] = {
{"stderr-progress",no_argument,NULL,'e'},
@@ -612,14 +618,15 @@
{"version",no_argument,NULL,'V'},
{"query",no_argument,NULL,'Q'},
{"help",no_argument,NULL,'h'},
- {"cache-test",no_argument,NULL,'U'},
+ {"analyze-drive",no_argument,NULL,'A'},
{"disable-paranoia",no_argument,NULL,'Z'},
{"disable-extra-paranoia",no_argument,NULL,'Y'},
{"abort-on-skip",no_argument,NULL,'X'},
{"disable-fragmentation",no_argument,NULL,'F'},
{"output-info",required_argument,NULL,'i'},
{"never-skip",optional_argument,NULL,'z'},
- {"log-summary",required_argument,NULL,'l'},
+ {"log-summary",optional_argument,NULL,'l'},
+ {"log-debug",optional_argument,NULL,'L'},
{NULL,0,NULL,0}
};
@@ -666,6 +673,11 @@
int batch=0,i;
int run_cache_test=0;
+ char *logfile_name=NULL;
+ char *reportfile_name=NULL;
+ int logfile_open=0;
+ int reportfile_open=0;
+
/* full paranoia, but allow skipping */
int paranoia_mode=PARANOIA_MODE_FULL^PARANOIA_MODE_NEVERSKIP;
@@ -771,9 +783,11 @@
case 'Z':
paranoia_mode=PARANOIA_MODE_DISABLE;
break;
- case 'U':
+ case 'A':
run_cache_test=1;
query_only=1;
+ reportfile_open=1;
+ verbose=CDDA_MESSAGE_PRINTIT;
break;
case 'z':
if (optarg) {
@@ -809,19 +823,19 @@
toc_offset=atoi(optarg);
break;
case 'l':
- if(logfile && logfile != stdout)fclose(logfile);
- if(!strcmp(optarg,"-"))
- logfile=stdout;
- else{
- logfile=fopen(optarg,"w");
- if(logfile==NULL){
- report("Cannot open log summary file %s: %s",(char*)optarg,
- strerror(errno));
- exit(1);
- }
- }
-
+ if(logfile_name)free(logfile_name);
+ logfile_name=NULL;
+ if(optarg)
+ logfile_name=strdup(optarg);
+ logfile_open=1;
break;
+ case 'L':
+ if(reportfile_name)free(reportfile_name);
+ reportfile_name=NULL;
+ if(optarg)
+ reportfile_name=strdup(optarg);
+ reportfile_open=1;
+ break;
case 'O':
sample_offset=atoi(optarg);
break;
@@ -831,18 +845,65 @@
}
}
+ if(logfile_open){
+ if(logfile_name==NULL)
+ logfile_name=strdup("cdparanoia.log");
+ if(!strcmp(logfile_name,"-")){
+ logfile=stdout;
+ logfile_open=0;
+ }else{
+ logfile=fopen(logfile_name,"w");
+ if(logfile==NULL){
+ report("Cannot open log summary file %s: %s",logfile_name,
+ strerror(errno));
+ exit(1);
+ }
+ }
+ }
+ if(reportfile_open){
+ if(reportfile_name==NULL)
+ reportfile_name=strdup("cdparanoia.log");
+ if(!strcmp(reportfile_name,"-")){
+ reportfile=stdout;
+ reportfile_open=0;
+ }else{
+ if(logfile_name && !strcmp(reportfile_name,logfile_name)){
+ reportfile=logfile;
+ reportfile_open=0;
+ }else{
+ reportfile=fopen(reportfile_name,"w");
+ if(reportfile==NULL){
+ report("Cannot open debug log file %s: %s",reportfile_name,
+ strerror(errno));
+ exit(1);
+ }
+ }
+ }
+ }
+
if(logfile){
/* log command line and version */
int i;
for (i = 0; i < argc; i++)
fprintf(logfile,"%s ",argv[i]);
fprintf(logfile,"\n");
-
- fprintf(logfile,VERSION);
- fprintf(logfile,"\n");
+
+ if(reportfile!=logfile){
+ fprintf(logfile,VERSION);
+ fprintf(logfile,"\n");
+ }
fflush(logfile);
}
+ if(reportfile && reportfile!=logfile){
+ /* log command line */
+ int i;
+ for (i = 0; i < argc; i++)
+ fprintf(reportfile,"%s ",argv[i]);
+ fprintf(reportfile,"\n");
+ fflush(reportfile);
+ }
+
if(optind>=argc && !query_only){
if(batch)
span=NULL;
@@ -887,7 +948,7 @@
report("\n");
exit(1);
}else
- report("");
+ report(" ");
}
}
@@ -959,18 +1020,20 @@
exit(1);
}
- if(force_cdrom_speed!=0){
- char buf[80];
- sprintf(buf,"\nAttempting to set speed to %dx... ",force_cdrom_speed);
- report(buf);
- if(cdda_speed_set(d,force_cdrom_speed)){
- report("\tFAILED.");
- exit(1);
- }else{
+ if(force_cdrom_speed==0)force_cdrom_speed=-1;
+ if(force_cdrom_speed!=-1){
+ report("\nAttempting to set speed to %dx... ",force_cdrom_speed);
+ }
+ if(cdda_speed_set(d,force_cdrom_speed)){
+ if(force_cdrom_speed!=-1){
+ report("\tFAILED. Continuing anyway...");
+ }
+ }else{
+ if(force_cdrom_speed!=-1){
report("\tdrive returned OK.");
}
}
-
+
if(run_cache_test)
return analyze_timing_and_cache(d);
@@ -1370,7 +1433,9 @@
cdda_close(d);
d=NULL;
- if(logfile && logfile != stdout)
+ if(logfile_open)
fclose(logfile);
+ if(reportfile_open)
+ fclose(reportfile);
return 0;
}
Modified: trunk/cdparanoia/report.c
===================================================================
--- trunk/cdparanoia/report.c 2008-08-25 20:39:42 UTC (rev 15200)
+++ trunk/cdparanoia/report.c 2008-08-26 07:24:36 UTC (rev 15201)
@@ -3,4 +3,4 @@
int quiet=0;
int verbose=CDDA_MESSAGE_FORGETIT;
-
+FILE *reportfile=NULL;
Modified: trunk/cdparanoia/report.h
===================================================================
--- trunk/cdparanoia/report.h 2008-08-25 20:39:42 UTC (rev 15200)
+++ trunk/cdparanoia/report.h 2008-08-26 07:24:36 UTC (rev 15201)
@@ -1,5 +1,10 @@
extern int verbose;
extern int quiet;
+extern FILE *reportfile;
-#define report(...) if(!quiet){fprintf(stderr, __VA_ARGS__);fputc('\n',stderr);}
-#define reportC(...) if(!quiet){fprintf(stderr, __VA_ARGS__);}
+#define report(...) {if(!quiet){fprintf(stderr, __VA_ARGS__);fputc('\n',stderr);} \
+ if(reportfile){fprintf(reportfile, __VA_ARGS__);fputc('\n',reportfile);}}
+#define reportC(...) {if(!quiet){fprintf(stderr, __VA_ARGS__);} \
+ if(reportfile){fprintf(reportfile, __VA_ARGS__);}}
+#define printC(...) {if(!quiet){fprintf(stderr, __VA_ARGS__);}}
+#define logC(...) {if(reportfile){fprintf(reportfile, __VA_ARGS__);}}
More information about the commits
mailing list