2 static char sfs_c_chdSid[] = "@(#)sfs_c_chd.c 2.1 97/10/23";
6 * Copyright (c) 1992-1997,2001 by Standard Performance Evaluation Corporation
8 * Standard Performance Evaluation Corporation (SPEC)
9 * 6585 Merchant Place, Suite 100
12 * This product contains benchmarks acquired from several sources who
13 * understand and agree with SPEC's goal of creating fair and objective
14 * benchmarks to measure computer performance.
16 * This copyright notice is placed here only to protect SPEC in the
17 * event the source is misused in any manner that is contrary to the
18 * spirit, the goals and the intent of SPEC.
20 * The source code is provided to the user or company under the license
21 * agreement for the SPEC Benchmark Suite for this product.
24 /*****************************************************************
26 * Copyright 1991,1992 Legato Systems, Inc. *
27 * Copyright 1991,1992 Auspex Systems, Inc. *
28 * Copyright 1991,1992 Data General Corporation *
29 * Copyright 1991,1992 Digital Equipment Corporation *
30 * Copyright 1991,1992 Interphase Corporation *
31 * Copyright 1991,1992 Sun Microsystems, Inc. *
33 *****************************************************************/
36 * -------------------------- sfs_c_chd.c -------------------------
38 * The sfs child. Routines to initialize child parameters,
39 * initialize test directories, and generate load.
42 * void child(int, float, int, char *);
43 * void init_fileinfo(void);
44 * void init_counters(void);
45 * sfs_fh_type * randfh(int, int, uint_t, sfs_state_type,
47 * int check_access(struct *stat)
48 * int check_fh_access();
51 * void check_call_rate(void);
52 * void init_targets(void);
53 * void init_dirlayout(void);
54 * void init_rpc(void);
55 * void init_testdir(void);
60 * 21-Aug-92 Wittle randfh() uses working set files array.
61 * init_fileinfo() sets up working set.
62 * 02-Jul-92 Teelucksingh Target file size now based on peak load
64 * 04-Jan-92 Pawlowski Added raw data dump hooks.
65 * 16-Dec-91 Wittle Created.
70 * ------------------------- Include Files -------------------------
83 #include <sys/types.h>
88 #include "sfs_c_def.h"
89 #include "sfs_m_def.h"
90 #include "rfs_c_def.h"
91 #include "generic_hash.h"
92 #include "nfsd_nfsfh_cust.h"
94 extern struct hostent *Server_hostent;
96 #define PROB_SCALE 1000L
97 #define _M_MODULUS 2147483647L /* (2**31)-1 */
99 #define _GROUP_DIVISOR 500
100 #define _FILES_PER_GROUP 4
101 #define _MIN_GROUPS 12
102 #define _WORKING_SET_AT_25_OPS_PER_SEC 975
105 * ----------------------- External Definitions -----------------------
107 extern uint32_t biod_clnt_call(CLIENT *, uint32_t, xdrproc_t, void *);
108 extern enum clnt_stat proc_header(CLIENT *cl, xdrproc_t xdr_results, void *results_ptr);
109 extern int biod_poll_wait(CLIENT *, uint32_t);
110 extern enum clnt_stat get_areply_udp (CLIENT * cl, uint32_t *xid, struct timeval *timeout);
111 extern char * parse_name (char * t, char * buf);
113 /* forward definitions for local functions */
114 static int init_rpc(void);
116 /* RFS: forward definitions for local functions */
118 static void init_signal();
119 extern void init_file_system (void);
120 extern void init_dep_tab (void);
121 static void read_trace(char * trace_file);
122 static void read_fh_map();
123 static void init_play (char * mount_point);
124 static void trace_play(void);
125 static void print_result(void);
126 static int get_nextop(void);
127 static int check_timeout(void);
128 static struct biod_req * get_biod_req(int dep_tab_index);
129 static int lookup_biod_req (int xid);
130 static void init_time_offset(void);
131 static void adjust_play_window (int flag, int * poll_timeout);
132 static int poll_and_get_reply (int usecs);
133 static char * nfs3_strerror(int status);
134 static void check_clock(void);
135 static double time_so_far1(void);
136 static double get_resolution(void);
137 static void usage(void);
138 void init_dep_tab_entry (int dep_index);
139 extern inline fh_map_t * lookup_fh (char * trace_fh );
140 static inline void finish_request (int biod_index, int dep_index, int status);
141 static inline void add_new_file_system_object (int proc, int dep_index, char * line, char * reply_line);
142 static inline char * find_lead_trace_fh(int proc, char * line);
145 * ------------- Per Child Load Generation Rate Variables -----------
147 static uint_t Calls_this_period; /* calls made during the current run period */
148 static uint_t Calls_this_test; /* calls made during the test so far */
149 static uint_t Reqs_this_period; /* reqs made during the current run period */
150 static uint_t Reqs_this_test; /* reqs made during the test so far */
151 static uint_t Sleep_msec_this_test; /* msec slept during the test so far */
152 static uint_t Sleep_msec_this_period;
153 static uint_t Previous_chkpnt_msec; /* beginning time of current run period */
154 static int Target_sleep_mspc; /* targeted sleep time per call */
156 static char io_buf[BUFSIZ]; /* io buffer for print out messages */
159 int Log_fd; /* log fd */
160 char Logname[NFS_MAXNAMLEN]; /* child processes sync logfile */
161 int Validate = 0; /* fake variable */
162 int Child_num = 0; /* fake: child index */
163 int Tcp = 0; /* We implement UDP first */
164 int Client_num = 1; /* fake: number of client */
169 * ------------------------- SFS Child -------------------------
174 printf("sfs3 hostname:mount_dir trace_file fh_map_file\n");
180 #ifdef NO_DEPENDENCY_TABLE
184 fh_map_t * fh_map_entry;
185 int req_num_with_new_fh = 0;
186 int req_num_with_discard_fh = 0;
187 int req_num_with_init_fh =0;
189 for (i=0; i<memory_trace_size; i++) {
190 line = memory_trace[i].line;
191 if (line[TRACE_COMMAND_REPLY_FLAG_POS]=='C') {
192 trace_fh = strstr (line, "fh");
193 RFS_ASSERT (trace_fh);
195 fh_map_entry = lookup_fh (trace_fh);
196 if (fh_map_entry && (fh_map_entry->flag==FH_MAP_FLAG_DISCARD) ) {
197 req_num_with_discard_fh ++;
201 req_num_with_init_fh ++;
203 req_num_with_new_fh ++;
205 dep_tab[dep_tab_size].disk_index = memory_trace[i].disk_index;
206 dep_tab[dep_tab_size].line = memory_trace[i].line;
207 if ((dep_tab_size%100000)==0)
208 printf ("dep_tab[%d].disk_index %d = memory_trace[%d].disk_index %d\n", dep_tab_size, dep_tab[dep_tab_size].disk_index, i, memory_trace[i].disk_index);
215 printf ("read_dep_tab, req_num_with_init_fh %d req_num_with_new_fh %d discard %d\n", req_num_with_init_fh, req_num_with_new_fh, req_num_with_discard_fh);
220 memset (&total_profile, 0, sizeof(total_profile));
222 memset (&execute_next_request_profile, 0, sizeof(execute_next_request_profile));
223 memset (&valid_get_nextop_profile, 0, sizeof(valid_get_nextop_profile));
224 memset (&invalid_get_nextop_profile, 0, sizeof(invalid_get_nextop_profile));
225 memset (&prepare_argument_profile, 0, sizeof(prepare_argument_profile));
226 memset (&biod_clnt_call_profile, 0, sizeof(biod_clnt_call_profile));
228 memset (&receive_next_reply_profile, 0, sizeof(receive_next_reply_profile));
229 memset (&valid_poll_and_get_reply_profile, 0, sizeof(valid_poll_and_get_reply_profile));
230 memset (&invalid_poll_and_get_reply_profile, 0, sizeof(invalid_poll_and_get_reply_profile));
231 memset (&decode_reply_profile, 0, sizeof(decode_reply_profile));
232 memset (&check_reply_profile, 0, sizeof(check_reply_profile));
233 memset (&add_create_object_profile, 0, sizeof(add_create_object_profile));
235 memset (&check_timeout_profile, 0, sizeof(check_timeout_profile));
236 memset (&adjust_play_window_profile, 0, sizeof(adjust_play_window_profile));
239 static char trace_file[256]="anon-lair62-011130-1200.txt";
240 int print_memory_usage()
242 printf("size of fh_map_t %d size of fh_map %d\n", sizeof(fh_map_t), sizeof(fh_map));
243 printf("sizeof dep_tab_t %d sizeof dep_tab %d\n", sizeof(dep_tab_t), sizeof(dep_tab));
244 printf("size of memory_trace_entry_t %d sizeof memory_trace %d\n", sizeof(memory_trace_entry_t), sizeof(memory_trace));
245 printf("size of CREATE3args %d\n", sizeof( CREATE3args));
246 printf("size of MKDIR3args %d\n", sizeof( MKDIR3args));
247 printf("size of READ3args %d\n", sizeof( READ3args));
248 printf("size of WRITE3args %d\n", sizeof( WRITE3args));
249 printf("size of RENAME3args %d\n", sizeof( RENAME3args));
250 printf("size of GETATTR3args %d\n", sizeof( GETATTR3args));
251 printf("size of SETATTR3args %d\n", sizeof( SETATTR3args));
252 printf("size of LINK3args %d\n", sizeof( LINK3args));
253 printf("size of SYMLINK3args %d\n", sizeof( SYMLINK3args));
254 printf("size of MKNOD3args %d\n", sizeof( MKNOD3args));
255 printf("size of RMDIR3args %d\n", sizeof( RMDIR3args));
256 printf("size of REMOVE3args %d\n", sizeof( REMOVE3args));
257 printf("size of LOOKUP3args %d\n", sizeof( LOOKUP3args));
258 printf("size of READDIR3args %d\n", sizeof( READDIR3args));
259 printf("size of READDIRPLUS3args %d\n", sizeof( READDIRPLUS3args));
260 printf("size of FSSTAT3args %d\n", sizeof( FSSTAT3args));
261 printf("size of FSINFO3args %d\n", sizeof( FSINFO3args));
262 printf("size of COMMIT3args %d\n", sizeof( COMMIT3args));
263 printf("size of ACCESS3args %d\n", sizeof( ACCESS3args));
264 printf("size of READLINK3args %d\n", sizeof( READLINK3args));
268 int main(int argc, char ** argv)
270 extern char * optarg;
272 int memory_trace_size;
274 if (argc==2 && !strcmp(argv[1],"-help")) {
278 print_memory_usage();
280 getmyhostname(lad_hostname, HOSTNAME_LEN);
284 * Get the uid and gid information.
291 Nfs_timers = Nfs_udp_timers;
297 //init_play ("capella:/p5/RFSFS");
300 //read_fh_map (argv[3]);
301 read_fh_map ("fh-path-map-play");
302 init_dep_tab(); /* and dep_tab_size */
303 //read_trace (argv[2]);
304 //read_trace ("anon-lair62-011130-1000.txt");
305 strcpy(trace_file, argv[2]);
306 read_trace (trace_file);
307 stage = READ_DEP_TAB_STAGE;
310 for (i=0; i<dep_tab_size; i++) {
311 RFS_ASSERT (dep_tab[i].flag == DEP_FLAG_FREE)
312 init_dep_tab_entry (i);
314 stage = TRACE_PLAY_STAGE;
316 printf ("trace_play\n");
325 nfs_version = NFS_V3;
328 /* Set up the signal handlers for all signals */
331 #if (defined(_XOPEN_SOURCE) || defined(USE_POSIX_SIGNALS))
332 struct sigaction sig_act, old_sig_act;
334 /* use XOPEN signal handling */
336 sig_act.sa_handler = generic_catcher;
337 (void)sigemptyset(&sig_act.sa_mask);
338 sig_act.sa_flags = 0;
340 /* signals handlers for signals used by sfs */
341 sig_act.sa_handler = sfs_cleanup;
342 if (sigaction(SIGINT,&sig_act,&old_sig_act) == -1) {
343 perror("sigaction failed: SIGINT");
347 sig_act.sa_handler = sfs_cleanup;
348 if (sigaction(SIGTERM,&sig_act,&old_sig_act) != 0) {
349 perror("sigaction failed: SIGTERM");
353 /* signals handlers for signals used by sfs */
354 (void) signal(SIGINT, sfs_cleanup);
355 // RFS (void) signal(SIGALRM, sfs_alarm);
356 (void) signal(SIGTERM, sfs_cleanup);
362 char * mount_point) /* Mount point for remote FS */
364 char namebuf[NFS_MAXNAMLEN] = "trace_play"; /* unique name for this program */
365 CLIENT * mount_client_ptr; /* Mount client handle */
368 (void) setvbuf(stderr, io_buf, _IOLBF, BUFSIZ);
370 sfs_Myname = namebuf;
373 * May require root priv to perform bindresvport operation
375 mount_client_ptr = lad_getmnt_hand(mount_point);
376 if (mount_client_ptr == NULL) {
381 * should be all done doing priv port stuff
384 if (init_rpc() == -1) {
385 (void) fprintf(stderr, "%s: rpc initialization failed\n", sfs_Myname);
386 (void) generic_kill(0, SIGINT);
392 * finish all priv bindresvport calls
395 if (setuid(Real_uid) != (uid_t)0) {
396 (void) fprintf(stderr,"%s: %s%s", sfs_Myname,
397 "cannot perform setuid operation.\n",
398 "Do `make install` as root.\n");
401 init_mount_point(0, mount_point, mount_client_ptr);
405 * Cleanup client handle for mount point
407 clnt_destroy(mount_client_ptr);
414 void read_trace (char * tracefile)
421 fp = fopen(tracefile, "r");
422 RFS_ASSERT (fp!=NULL);
423 while (fgets(buf, 1024, fp)) {
424 //printf ("buf: %s buf[36] %c\n", buf, buf[36]);
425 //if (buf[36]=='C' || strstr(buf, "create") || strstr(buf, "lookup")) {
426 #ifdef REDUCE_MEMORY_TRACE_SIZE
427 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]=='C' || strstr(buf, "create") ||
428 strstr(buf, "mkdir") || strstr(buf, "symlink") || strstr(buf, "mknod") || strstr(buf, "lookup")) {
430 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
431 printf("strlen(buf) %d buf %s \n", strlen(buf), buf);
432 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
434 /* store the request to memory */
435 strcpy (memory_trace[memory_trace_size].line, buf);
436 memory_trace[memory_trace_size].disk_index = disk_index;
437 memory_trace_size ++;
439 if (memory_trace_size >= MAX_MEMORY_TRACE_LINES) {
440 fprintf (stderr, "memory trace size %d is not enough\n", MAX_MEMORY_TRACE_LINES);
443 if ((disk_index%100000)==0)
444 fprintf(stderr, "%d disk trace parsed, store %d trace lines to memory\n", disk_index, memory_trace_size);
445 #ifdef REDUCE_MEMORY_TRACE_SIZE
447 RFS_ASSERT (buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R');
453 fprintf(stderr, "total %d disk lines %d memory lines \n", disk_index, memory_trace_size );
458 #ifdef REDUCE_MEMORY_TRACE_SIZE
459 inline int disk_index_to_memory_index (int disk_index)
461 static int memory_index = 0;
462 if (disk_index > memory_trace[memory_index].disk_index) {
463 while (memory_trace[memory_index].disk_index < disk_index) {
465 RFS_ASSERT (memory_index < MAX_MEMORY_TRACE_LINES);
468 if (disk_index < memory_trace[memory_index].disk_index) {
469 while (memory_trace[memory_index].disk_index > disk_index) {
471 RFS_ASSERT (memory_index >=0);
475 RFS_ASSERT (disk_index == memory_trace[memory_index].disk_index);
479 #define disk_index_to_memory_index(disk_index) disk_index
482 #define get_line_by_disk_index(disk_index) \
483 memory_trace[disk_index_to_memory_index(disk_index)].line
485 inline char * find_reply_line (char * command_line, int cur_disk_index)
490 int request_memory_index = disk_index_to_memory_index (cur_disk_index);
491 for (i=request_memory_index+1; i<request_memory_index+MAX_COMMAND_REPLY_DISTANCE && i<MAX_MEMORY_TRACE_LINES; i++) {
492 line = memory_trace[i].line;
493 if (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
494 p = strchr (&line[TRACE_MSGID_POS], ' ');
496 if (!strncmp(&line[TRACE_MSGID_POS], &command_line[TRACE_MSGID_POS], p-&(line[TRACE_MSGID_POS])))
503 inline int find_reply_status (char * line)
508 //printf ("line %s flag %c\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
509 RFS_ASSERT (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R');
510 p = line+TRACE_MSGID_POS+2; /* at least one letter for msgid and one letter for space */
513 if (strstr(p, "lookup 2"))
515 if (strstr(p, "create d"))
517 if (strstr(p, "setattr 1"))
519 if (strstr(p, "lookup d"))
521 if (strstr(p, "read d"))
523 if (strstr(p, "write d"))
525 if (strstr(p, "mkdir d"))
527 printf ("line %s flag %c\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
531 inline int find_reply_status_old (char * line)
536 //printf ("line %s flag %c\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
537 RFS_ASSERT (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R');
538 if (!strstr(line, "OK")) {
539 p=strstr(line, " 6 read ");
541 p+=strlen(" 6 read ");
543 p = strstr (line, "status=XXX");
546 RFS_ASSERT (*p==' ');
554 sscanf (p, "%x", &i);
555 if ((i<=0) || (i>10000))
556 printf("line %s\n", line);
557 RFS_ASSERT (i>0 && i<10009);
562 inline char * find_reply_trace_fh (char * line)
565 p = strstr (line, "OK fh");
567 printf ("find_reply_trace_fh line %s\n", line);
572 inline int disk_index_to_dep_index(int cur_dep_index, int disk_index)
575 for (i=cur_dep_index; i>min_dep_index; i--) {
576 if (dep_tab[i].disk_index == disk_index)
582 inline int is_play_candidate (int dep_index)
584 int proc = dep_tab[dep_index].proc;
585 int status = dep_tab[dep_index].status;
586 int trace_status = dep_tab[dep_index].trace_status;
588 #ifndef TAKE_CARE_CREATE_MODE_BY_DAN
589 /* for a failed create in trace, trace_replay just ignore many time the trace create fail
590 * due to access control, but trace_play will success because our access control
591 * may be loose (all uid/gid is mapped to single one 513:513, so we just skip these requests
593 if ((proc==CREATE || proc==MKDIR) && (trace_status!=NFS3_OK) && (status!=NFS3ERR_RFS_MISS)) {
594 if (dependency_debug)
595 printf ("disk[%d] ignore failed create/mkdir in trace, trace_status %d line %s",
596 dep_tab[dep_index].disk_index, trace_status, dep_tab[dep_index].line);
597 failed_create_command_num ++;
601 #ifndef TAKE_CARE_OTHER_FAILED_COMMAND
602 if (((trace_status == NFS3ERR_ACCES) && (proc==READ || proc==WRITE || proc==LOOKUP)) ||
603 ((trace_status == NFS3ERR_PERM) && (proc==SETATTR)) ){
604 if (dependency_debug)
605 printf ("disk[%d] ignore other failed command in trace, trace_status %d line %s",
606 dep_tab[dep_index].disk_index, trace_status, dep_tab[dep_index].line);
608 failed_other_command_num ++;
612 #ifndef TAKE_CARE_SYMBOLIC_LINK
613 if ((dep_tab[dep_index].proc==READLINK) ) { /* send request */
614 skipped_readlink_command_num ++;
618 #define TAKE_CARE_CUSTOM_COMMAND
619 /* This is actually take care in get_nextop by checking fh_map error when dep_index==min_dep_index */
620 #ifndef TAKE_CARE_CUSTOM_COMMAND
621 /* this line has a file handle which should belong to discard but it is not
622 * the file handle directly appears as parent directory in a lookup request
623 * the return value is NOENT, the parent directory should have been initialized
624 * but the initialization code just ignored all lookup request which didn't success
625 * including NOENT even though the parent directory is still valid.
627 if (( ((dep_tab[dep_index].disk_index==262213) || (dep_tab[dep_index].disk_index==214402))
628 && !(strcmp(trace_file, "anon-lair62-011130-1100.txt"))
630 ( ((dep_tab[dep_index].disk_index==238460) || (dep_tab[dep_index].disk_index ==238470))
631 && !(strcmp(trace_file, "anon-lair62-011130-1000.txt"))
633 skipped_custom_command_num++;
637 #ifndef TAKE_CARE_FSSTAT_COMMAND
638 /* the file handle used in this command is not processed properly by pre-processing */
640 char * trace_fh = find_lead_trace_fh(proc, dep_tab[dep_index].line);
641 fh_map_t * fh = lookup_fh (trace_fh);
643 skipped_fsstat_command_num++;
651 inline int is_dir_op (int proc)
668 inline int is_create_op (int proc)
670 if (proc==CREATE || proc==MKDIR || proc==LINK || proc==SYMLINK || proc==MKNOD || proc==RENAME)
675 inline int is_delete_op (int proc)
677 if (proc==REMOVE || proc==RMDIR || proc==RENAME)
682 static inline char * find_lead_trace_fh(int proc, char * line)
685 /* check the file handle availability */
686 p = strstr (line, "fh");
688 p+=3; //printf ("check dependency dep_tab[%d] trace_fh %s line %s \n", dep_index, trace_fh, line);
692 inline char * find_another_trace_fh(int proc, char * line)
695 /* check the file handle availability */
696 p = strstr (line, "fh2");
698 p+=4; //printf ("check dependency dep_tab[%d] trace_fh %s line %s \n", dep_index, trace_fh, line);
702 /* return the index of next request in dep_tab.
703 * Return -1 if there is no suitable request to send
705 inline int get_nextop(void)
709 static int dep_index = -2;
712 static int min_wait_fhandle_dep_index = DEP_TAB_SIZE;
716 //if (dep_index < min_dep_index-1)
717 // dep_index = min_dep_index-1;
719 dep_index = min_dep_index-1;
720 for (i=0; i<max_dep_index-min_dep_index; i++) {
722 if (dep_index == max_dep_index) {
723 dep_index = min_dep_index;
726 proc = dep_tab[dep_index].proc;
727 flag = dep_tab[dep_index].flag;
729 if (dependency_debug)
730 printf ("get_nextop check dep_tab[%d].disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
731 #ifdef NO_DEPENDENCY_TABLE
732 if (dep_tab[dep_index].flag == DEP_FLAG_INIT) {
733 if (is_play_candidate(dep_index)==TRUE) {
734 /* the trace_fh is the file handle for the operation directory, trace_fh_2 is other file handle
735 * used in the request */
736 if (proc==LINK || proc==RENAME) {
737 dep_tab[dep_index].trace_fh = find_another_trace_fh (proc, dep_tab[dep_index].line);
738 dep_tab[dep_index].trace_fh_2 = find_lead_trace_fh(proc, dep_tab[dep_index].line);
739 dep_tab[dep_index].fh = 0;
740 dep_tab[dep_index].fh_2 = 0;
742 dep_tab[dep_index].trace_fh = find_lead_trace_fh(proc, dep_tab[dep_index].line);
743 dep_tab[dep_index].fh = 0;
744 dep_tab[dep_index].fh_2 = (fh_map_t *)1;
746 dep_tab[dep_index].flag = DEP_FLAG_CANDIDATE;
748 dep_tab[dep_index].skip_sec = skip_sec;
750 if (dependency_debug)
751 printf ("disk[%d] state DEP_FLAG_INIT to DEP_FLAG_CANDIDATE\n", dep_tab[dep_index].disk_index);
753 if (dependency_debug)
754 printf ("disk[%d] state DEP_FLAG_INIT to DEP_FLAG_DONE\n", dep_tab[dep_index].disk_index);
755 dep_tab[dep_index].flag = DEP_FLAG_DONE;
760 if ((dep_tab[dep_index].flag == DEP_FLAG_CANDIDATE) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_FHANDLE) ) {
762 if (!dep_tab[dep_index].fh)
763 dep_tab[dep_index].fh = lookup_fh (dep_tab[dep_index].trace_fh);
764 if (!dep_tab[dep_index].fh_2)
765 dep_tab[dep_index].fh_2 = lookup_fh (dep_tab[dep_index].trace_fh_2);
767 /* need to wait for file handle */
768 if ((!dep_tab[dep_index].fh) || (!dep_tab[dep_index].fh_2)) {
769 if (dependency_debug)
770 printf("disk[%d] can not lookup file handle\n", dep_tab[dep_index].disk_index);
771 if (dep_tab[dep_index].flag == DEP_FLAG_CANDIDATE) {
772 if (dependency_debug)
773 printf ("disk[%d] state DEP_FLAG_CANDIDATE to DEP_FLAG_WAIT_FHANDLE\n", dep_tab[dep_index].disk_index);
774 dep_tab[dep_index].flag = DEP_FLAG_WAIT_FHANDLE;
775 sfs_gettime (&dep_tab[dep_index].start);
776 if (dep_index < min_wait_fhandle_dep_index)
777 min_wait_fhandle_dep_index = dep_index;
780 if (dep_index==min_dep_index) {
782 printf ("fh_path_map error disk[%d] state DEP_FLAG_WAIT_FHANDLE to DEP_FLAG_DONE\n", dep_tab[dep_index].disk_index);
783 fh_path_map_err_num ++;
784 dep_tab[dep_index].flag = DEP_FLAG_DONE;
788 SUBTIME (tmp, dep_tab[dep_index].start);
789 #define DEPENDENCY_TIMEOUT 5
791 RFS_ASSERT (tmp.sec < DEPENDENCY_TIMEOUT + (skip_sec - dep_tab[dep_index].skip_sec));
793 if (tmp.sec >= DEPENDENCY_TIMEOUT) {
794 printf("dep_tab[%d].flag %d disk_index %d line %s\n", dep_index,
795 dep_tab[dep_index].flag, dep_tab[dep_index].disk_index,
796 dep_tab[dep_index].line);
798 RFS_ASSERT (tmp.sec < DEPENDENCY_TIMEOUT );
804 /* file handle ready, adjust_min_wait_fhandle_dep_index */
805 if ((dep_tab[dep_index].flag == DEP_FLAG_WAIT_FHANDLE)) {
806 if (dep_index == min_wait_fhandle_dep_index) {
807 min_wait_fhandle_dep_index = dep_tab_size;
808 for (j=dep_index+1; j<max_dep_index; j++) {
809 if (dep_tab[j].flag ==DEP_FLAG_WAIT_FHANDLE) {
810 min_wait_fhandle_dep_index = j;
816 if (dependency_debug)
817 printf("disk[%d] found file handle\n", dep_tab[dep_index].disk_index);
818 dep_tab[dep_index].flag = DEP_FLAG_FHANDLE_READY;
820 /* the normal file operation can be executed now */
821 if (!is_dir_op (dep_tab[dep_index].proc)) {
822 if (dependency_debug)
823 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
827 if (dependency_debug)
828 printf("disk[%d] directory operation \n", dep_tab[dep_index].disk_index);
829 /* the directory operation need to lock the directory first */
830 if (dep_tab[dep_index].fh->lock) {
831 if (dependency_debug)
832 printf ("disk[%d] state %d to DEP_FLAG_WAIT_DIRECTORY\n", dep_tab[dep_index].disk_index, dep_tab[dep_index].flag);
833 dep_tab[dep_index].flag = DEP_FLAG_WAIT_DIRECTORY;
838 if ((dep_tab[dep_index].flag == DEP_FLAG_FHANDLE_READY) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_DIRECTORY)) {
839 int j = dep_tab[dep_index].fh - fh_map;
840 if (dependency_debug) {
841 printf ("dep_tab[%d].disk_index %d, fh_map[%d] lock=%d\n",dep_index, dep_tab[dep_index].disk_index, j, dep_tab[dep_index].fh->lock);
842 printf ("trace_fh %s path %s\n", dep_tab[dep_index].fh->trace_fh, dep_tab[dep_index].fh->path);
843 printf ("trace_fh %s path %s\n", fh_map[j].trace_fh, fh_map[j].path);
845 if ((dep_tab[dep_index].fh->lock) || ((proc==RENAME) && (dep_tab[dep_index].fh_2->lock)) ) {
846 if (dependency_debug)
847 printf ("continue to wait for directory lock\n");
850 if (dependency_debug)
851 printf ("dep_tab[%d] disk index %d LOCK fh_map[%d] \n", dep_index, dep_tab[dep_index].disk_index, j);
852 dep_tab[dep_index].fh->lock = 1;
854 dep_tab[dep_index].fh_2->lock = 1;
856 /* the non-delete directory operation can proceed now */
857 if (!is_delete_op (dep_tab[dep_index].proc)) {
858 if (dependency_debug)
859 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
863 /* the delete operation can proceed if nobody ahead is waiting for fhandle */
864 /* probably this condition is not strong enough */
865 // if ((min_wait_fhandle_dep_index<dep_index) ) {
866 if (dep_index!=min_dep_index) {
867 if (dependency_debug)
868 printf ("disk[%d] state %d to DEP_FLAG_WAIT_DELETE\n", dep_tab[dep_index].disk_index, dep_tab[dep_index].flag);
869 dep_tab[dep_index].flag = DEP_FLAG_WAIT_DELETE;
872 dep_tab[dep_index].flag = DEP_FLAG_DIRECTORY_READY;
875 if ((dep_tab[dep_index].flag == DEP_FLAG_DIRECTORY_READY) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_DELETE)) {
876 // if (min_wait_fhandle_dep_index > dep_index) {
877 if (dep_index==min_dep_index) {
878 if (dependency_debug)
879 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
884 if (dep_tab[dep_index].flag == DEP_FLAG_INIT){
885 for (j=0, t=&(dep_tab[dep_index].dep_ops[0]);
886 (j<dep_tab[dep_index].init_dep_num) && (dep_tab[dep_index].cur_dep_num>0);
889 if (dep_tab[disk_index_to_dep_index(dep_index, *t)].flag == DEP_FLAG_DONE) {
890 /* The depended request has been finished */
892 dep_tab[dep_index].cur_dep_num --;
897 if (dep_tab[dep_index].cur_dep_num == 0) {
904 if (dependency_debug)
905 printf ("get_nexop return -1\n");
909 int check_timeout(void)
911 static int biod_index = 0;
913 int dep_index; /* index into dep_tab */
915 sfs_op_type *op_ptr; /* per operation info */
916 struct ladtime timeout;
918 sfs_gettime (¤t);
920 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
921 if (biod_reqp[biod_index].in_use==TRUE) {
922 timeout = biod_reqp[biod_index].timeout;
923 if ((current.sec>timeout.sec) ||
924 ((current.sec==timeout.sec) && (current.usec>timeout.usec))) {
926 dep_index = biod_reqp[biod_index].dep_tab_index;
927 proc = dep_tab[dep_index].proc;
929 op_ptr->results.timeout_calls++;
930 Ops[TOTAL].results.timeout_calls++;
932 finish_request (biod_index, dep_index, NFS3ERR_RFS_TIMEOUT);
934 if (is_create_op(proc)) {
935 dep_tab[dep_index].flag = DEP_FLAG_CANDIDATE;
936 printf ("resend dep_tab[%d], disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
938 //RFS_ASSERT (!is_create_op(proc));
940 //printf ("timeout request: biod_reqp[%d].start %d:%d timeout %d:%d current %d:%d\n", biod_index, biod_reqp[biod_index].start.sec, biod_reqp[biod_index].start.usec, timeout.sec, timeout.usec, current.sec, current.usec);
946 /* Allocate a biod_req entry to send and receive request dep_tab[dep_index]
947 * build the cross reference between dep_tab entry and biod_req entry
949 struct biod_req * get_biod_req(int dep_index) /* index into dep_tab */
951 static int biod_index = 0;
953 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
954 if (!biod_reqp[biod_index].in_use) {
955 biod_reqp[biod_index].in_use = 1;
956 biod_reqp[biod_index].dep_tab_index = dep_index;
957 dep_tab[dep_index].biod_req_index = biod_index;
958 return &(biod_reqp[biod_index]);
964 /* Return index into biod_reqp
965 * return -1 upon failure
967 int lookup_biod_req (int xid)
969 static int biod_index = 0;
971 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
972 /* give a NULL as timeout pointer may cause indefinitely block */
973 if (biod_reqp[biod_index].xid == xid) {
980 extern struct ladtime test_start;
981 void init_time_offset(void)
988 sfs_gettime (&tmp1); /* called at initial time: tmp1 = play_starttime */
990 DIVTIME (tmp1, PLAY_SCALE) /* tmp1 = play_starttime / SCALE */
993 MULTIME (tmp1, PLAY_SCALE) /* tmp1 = play_starttime * SCALE */
996 tmp2 = trace_starttime; /* tmp2 = trace_starttime */
997 SUBTIME (tmp2, tmp1); /* tmp2 = trace_starttime - play_starttime *|/ SCALE */
998 time_offset = tmp2; /* time_offset = trace_starttime - play_starttime *|/ SCALE */
1001 /* initialize timestamp and proc field of dep_tab entry */
1002 void init_dep_tab_entry (int dep_index)
1004 static int nfs2proc_to_rfsproc[18] = {0, 1, 2, 3, 4, 5, 6, 7, 8, 9,
1005 10, 11, 12, 13, 14, 15, 16, 17};
1006 static int nfs3proc_to_rfsproc[NFS3_PROCEDURE_COUNT] = {0, 1, 2, 4, 18, 5, 6, 8, 9, 14,
1007 13, 21, 10, 15, 11, 12, 16, 23, 17, 20,
1014 //line = get_line_by_disk_index (dep_tab[dep_index].disk_index);
1015 line = dep_tab[dep_index].line;
1016 sscanf (line, "%d.%d", &(dep_tab[dep_index].timestamp.tv_sec), &(dep_tab[dep_index].timestamp.tv_usec));
1017 sscanf (&line[39], "%x %x", &msgid, &nfsproc);
1018 if (line[TRACE_VERSION_POS]=='2') {
1019 dep_tab[dep_index].proc = nfs2proc_to_rfsproc[nfsproc];
1020 RFS_ASSERT (nfsproc <18);
1022 /* This is for debug purpose */
1023 if (line[TRACE_VERSION_POS] !='3') {
1024 fprintf(stderr, "line[TRACE_VERSION_POS] %c line %s\n", line[TRACE_VERSION_POS], line);
1025 line = get_line_by_disk_index (dep_tab[dep_index].disk_index-1);
1027 line = get_line_by_disk_index (dep_tab[dep_index].disk_index-2);
1029 fprintf(stderr, "previousline %s\n", line);
1031 RFS_ASSERT (line[TRACE_VERSION_POS] =='3');
1032 if (nfsproc >= NFS3_PROCEDURE_COUNT) {
1033 fprintf(stderr, "proc %d line %s\n", nfsproc, line);
1036 RFS_ASSERT (nfsproc <NFS3_PROCEDURE_COUNT);
1037 dep_tab[dep_index].proc = nfs3proc_to_rfsproc[nfsproc];
1039 RFS_ASSERT (dep_tab[dep_index].proc >= 0 && dep_tab[dep_index].proc < NOPS);
1040 dep_tab[dep_index].flag = DEP_FLAG_INIT;
1041 dep_tab[dep_index].reply_line = find_reply_line (line, dep_tab[dep_index].disk_index);
1042 if (dep_tab[dep_index].reply_line == NULL) {
1043 //printf ("disk[%d] can not find the reply line, assume trace_status OK\n", dep_tab[dep_index].disk_index);
1044 dep_tab[dep_index].trace_status = NFS3ERR_RFS_MISS;
1045 missing_reply_num ++;
1047 dep_tab[dep_index].trace_status = find_reply_status (dep_tab[dep_index].reply_line);
1050 static void adjust_play_window (int flag, int * poll_timeout)
1052 struct ladtime max_window_time;
1053 static struct ladtime max_poll_time = {0, 2000, 0};
1055 int old_min = min_dep_index;
1056 int old_max = max_dep_index;
1060 for (; (dep_tab[min_dep_index].flag == DEP_FLAG_DONE) && (min_dep_index<dep_tab_size); min_dep_index++)
1062 RFS_ASSERT (min_dep_index <= max_dep_index);
1064 /* max_trace_window_time = current *|/ SCALE + trace_starttime */
1065 sfs_gettime (¤t);
1069 MULTIME (current, PLAY_SCALE);
1072 DIVTIME (current, PLAY_SCALE);
1074 ADDTIME (current, trace_starttime);
1075 max_window_time = current;
1077 while ((max_dep_index<min_dep_index+MAX_PLAY_WINDOW) && (max_dep_index<dep_tab_size))
1079 t.sec = dep_tab[max_dep_index].timestamp.tv_sec;
1080 t.usec = dep_tab[max_dep_index].timestamp.tv_usec;
1082 if (adjust_play_window_debug)
1083 printf ("max_window_time sec %d usec %d : max_dep_index %d, t.sec %d t.usec %d\n", max_window_time.sec, max_window_time.usec, max_dep_index, t.sec, t.usec );
1085 if ((t.sec>max_window_time.sec)||(t.sec==max_window_time.sec && t.usec>max_window_time.usec))
1091 /* Right now it is not clear how to deal with the situation where MAX_PLAY_WINDOW is reached */
1092 if (max_dep_index == min_dep_index+MAX_PLAY_WINDOW) {
1093 //printf ("can not catch up the speed, max_dep_index %d reach min_dep_index %d+MAX_PLAY_WINDOW\n", max_dep_index, min_dep_index);
1095 can_not_catch_speed_num ++;
1097 //RFS_ASSERT (max_dep_index < min_dep_index+MAX_PLAY_WINDOW);
1099 ADDTIME (current, trace_starttime);
1100 max_window_time = current;
1101 max_dep_index = min_dep_index + MAX_PLAY_WINDOW;
1102 if (max_dep_index >dep_tab_size)
1103 max_dep_index = dep_tab_size;
1108 else if (max_dep_index == dep_tab_size) {
1109 *poll_timeout = 1000000; /* poll_timeout set to 1 second for the last request */
1113 struct ladtime tmp1;
1114 tmp.sec = dep_tab[max_dep_index].timestamp.tv_sec;
1115 tmp.usec = dep_tab[max_dep_index].timestamp.tv_usec;
1116 if (adjust_play_window_debug)
1117 printf ("dep_tab[max_dep_index %d].timestamp %d:%d, max_window_time %d:%d\n",
1118 max_dep_index, tmp.sec, tmp.usec, max_window_time.sec, max_window_time.usec);
1120 SUBTIME (tmp, max_window_time);
1122 DIVTIME (tmp, PLAY_SCALE);
1125 MULTIME (tmp, PLAY_SCALE);
1129 if (tmp.sec > max_poll_time.sec) {
1132 printf ("dep_tab[%d].timestamp %d:%d, max_window_time %d:%d\n",
1133 max_dep_index, dep_tab[max_dep_index].timestamp.tv_sec, dep_tab[max_dep_index].timestamp.tv_usec, max_window_time.sec, max_window_time.usec);
1134 printf ("skip %d seconds\n", tmp.sec-max_poll_time.sec);
1135 SUBTIME (tmp, max_poll_time);
1137 skip_sec += tmp.sec;
1138 SUBTIME (test_start, tmp);
1139 tmp = max_poll_time;
1142 RFS_ASSERT ((tmp.sec < 1000));
1143 if ((tmp.sec ==0) && (tmp.usec==0)) {
1146 *poll_timeout = tmp.sec*1000000+tmp.usec;
1150 struct ladtime tmp1;
1151 tmp.sec = dep_tab[max_dep_index].timestamp.tv_sec;
1152 tmp.usec = dep_tab[max_dep_index].timestamp.tv_usec;
1153 tmp1.sec = dep_tab[max_dep_index-1].timestamp.tv_sec;
1154 tmp1.usec = dep_tab[max_dep_index-1].timestamp.tv_usec;
1155 SUBTIME (tmp, tmp1);
1156 RFS_ASSERT ((tmp.sec < 1000));
1157 RFS_ASSERT ((tmp.sec>0) || ((tmp.sec==0) && (tmp.usec>0)));
1158 *poll_timeout = tmp.sec*1000000+tmp.usec;
1161 *poll_timeout = 100000;
1165 printf ("adjust_play_window: flag %d min %d -> %d, max %d -> %d poll_timeout %d \n", flag, old_min, min_dep_index, old_max, max_dep_index, *poll_timeout);
1168 /* poll for usecs and receive, after receive one reply,
1169 * return index in biod_reqp of the corresponding request
1171 int poll_and_get_reply (int usecs)
1173 int biod_index = -1;
1176 struct timeval zero_time = {0, 0}; /* Immediately return */
1179 error = biod_poll_wait (NFS_client, usecs);
1182 if (errno == EINTR) {
1187 (void) fprintf(stderr, "biod_poll_wait error\n");
1189 (void) fflush(stderr);
1196 error = get_areply_udp (NFS_client, &xid, &zero_time);
1197 // RFS_ASSERT (error!= RPC_TIMEOUT); /* we have polled and know there is data */
1198 // RFS_ASSERT (error!= RPC_CANTRECV);
1199 RFS_ASSERT (error == RPC_SUCCESS);
1201 biod_index = lookup_biod_req (xid);
1202 sfs_gettime (&(biod_reqp[biod_index].stop));
1211 void print_result(void)
1217 unsigned long long tmp;
1220 if (DEBUG_CHILD_GENERAL) {
1221 (void) fprintf(stdout, "trace play result:\n");
1222 (void) fprintf(stdout, "\t percentage good_cnt bad_cnt timeout_cnt\telapsed time\t\t\taverage time\n");
1223 for (i=0; i<NOPS+1; i++) {
1224 if (Ops[i].results.good_calls==0) {
1228 tmp = Ops[i].results.time.sec*1000000 + Ops[i].results.time.usec;
1230 avg_usecs = tmp/Ops[i].results.good_calls;
1232 avg_msecs = (Ops[i].results.time.sec*1000 + Ops[i].results.time.usec/1000)/Ops[i].results.good_calls;
1233 avg_usecs = (Ops[i].results.time.usec%1000)/Ops[i].results.good_calls;
1236 (void) fprintf(stdout, "%11s\t%4.1f\t%4d\t%4d\t%4d\t\tsec %8d usec %8d \tusec %8d\n",
1238 (float)(100*Ops[i].results.good_calls)/(float)Ops[TOTAL].results.good_calls,
1239 Ops[i].results.good_calls, Ops[i].results.bad_calls, Ops[i].results.timeout_calls,
1240 Ops[i].results.time.sec, Ops[i].results.time.usec, avg_msecs*1000+avg_usecs);
1242 (void) fflush (stdout);
1245 RFS_ASSERT (read_data_owe_GB==0);
1246 printf("read_data_bytes %d owe %d GB and %d bytes, %d percent, adjusted %d times \n",read_data_total, read_data_owe_GB, read_data_owe, (read_data_owe_GB*1073741824+read_data_owe)/(read_data_total/100), read_data_adjust_times);
1247 printf("write_data_bytes %d owe %d GB and %d bytes, %d percent, adjusted %d times \n",write_data_total, write_data_owe_GB, write_data_owe, (write_data_owe_GB*1073741824+write_data_owe)/(write_data_total/100), write_data_adjust_times);
1248 printf("poll_timeout_0_num %d poll_timeout_pos_num %d\n", poll_timeout_0_num, poll_timeout_pos_num);
1249 printf("failed_create_command_num %d\nfailed_other_command_num %d\nskipped_readlink_command_num %d\nskipped_custom_command_num %d\nfh_path_map_err_num %d\nskipped_fsstat_command_num %d\nmissing_reply_num %d\nrename_rmdir_noent_reply_num %d\nrmdir_not_empty_reply_num %d\nloose_access_control_reply_num %d\nlookup_err_due_to_rename %d\nlookup_eaccess_enoent_mismatch %d\nread_io_err_num %d\nproper_reply_num %d\n",
1250 failed_create_command_num,
1251 failed_other_command_num,
1252 skipped_readlink_command_num,
1253 skipped_custom_command_num,
1254 fh_path_map_err_num,
1255 skipped_fsstat_command_num,
1257 rename_rmdir_noent_reply_num,
1258 rmdir_not_empty_reply_num,
1259 loose_access_control_reply_num,
1260 lookup_err_due_to_rename_num,
1261 lookup_eaccess_enoent_mismatch_num,
1265 clnt_destroy(NFS_client);
1268 // print_dump(Client_num, Child_num);
1271 printf ("[%4d] %s \tstart %4d:%6d \n",
1272 dep_index, Ops[dep_tab[dep_index].proc].name, dep_tab[dep_index].start.sec, dep_tab[dep_index].start.usec);
1273 for (i=1; i<dep_tab_size*2; i++) {
1274 dep_index = event_order[i];
1276 printf ("[%4d] %s \tstart %4d:%6d \n",
1277 dep_index, Ops[dep_tab[dep_index].proc].name, dep_tab[dep_index].start.sec, dep_tab[dep_index].start.usec);
1279 dep_index = -dep_index;
1280 t=dep_tab[dep_index].stop;
1281 SUBTIME (t, dep_tab[dep_index].start);
1282 printf ("\t\t\t\t\t[%4d] %s stop %4d:%6d\tinterval %4d:%6d %s\n",
1283 dep_index, Ops[dep_tab[dep_index].proc].name, dep_tab[dep_index].stop.sec, dep_tab[dep_index].stop.usec, t.sec, t.usec, nfs3_strerror(dep_tab[dep_index].status));
1288 for (i=0, j=0; i<dep_tab_size || j<dep_tab_size; ) {
1289 if ((i==dep_tab_size) ||
1290 (LARGERTIME(dep_tab[i].start, dep_tab[j].stop) && j<dep_tab_size)) {
1292 SUBTIME (t, dep_tab[j].start);
1293 printf ("dep_tab[%d].proc %s stop %d:%d interval %d:%d status %s\n",
1294 j, Ops[dep_tab[j].proc].name, dep_tab[j].stop.sec, dep_tab[j].stop.usec, t.sec, t.usec, nfs3_strerror(dep_tab[j].status));
1297 printf ("dep_tab[%d].proc %s start %d:%d \n",
1298 i, Ops[dep_tab[i].proc].name, dep_tab[i].start.sec, dep_tab[i].start.usec);
1306 * allocate and initialize client handles
1314 * Set up the client handles. We get them all before trying one
1315 * out to insure that the client handle for LOOKUP class is allocated
1316 * before calling op_getattr().
1318 if (DEBUG_CHILD_GENERAL) {
1319 (void) fprintf(stderr, "%s: set up client handle\n", sfs_Myname);
1322 NFS_client = lad_clnt_create(Tcp? 1: 0, Server_hostent,
1323 (uint32_t) NFS_PROGRAM,
1324 (uint32_t) nfs_version,
1325 RPC_ANYSOCK, &Nfs_timers[0]);
1327 if (NFS_client == ((CLIENT *) NULL)) {
1332 * create credentials using the REAL uid
1334 NFS_client->cl_auth = authunix_create(lad_hostname, (int)Real_uid,
1335 (int)Cur_gid, 0, NULL);
1338 if (biod_init(dummy, dummy) == -1) {
1351 /* Ready to go - initialize operation counters */
1352 for (i = 0; i < NOPS + 1; i++) {
1354 Ops[i].results.good_calls = 0;
1355 Ops[i].results.bad_calls = 0;
1356 Ops[i].results.timeout_calls = 0; // RFS
1357 Ops[i].results.fast_calls = 0;
1358 Ops[i].results.time.sec = 0;
1359 Ops[i].results.time.usec = 0;
1360 Ops[i].results.msec2 = 0;
1363 /* initialize timers and period variables */
1364 sfs_gettime(&Starttime);
1365 Cur_time = Starttime;
1366 start_msec = (Starttime.sec * 1000) + (Starttime.usec / 1000);
1367 Previous_chkpnt_msec = start_msec;
1368 Calls_this_period = 0;
1369 Reqs_this_period = 0;
1370 Sleep_msec_this_period = 0;
1371 Calls_this_test = 0;
1373 Sleep_msec_this_test = 0;
1377 nfs3_strerror(int status)
1379 static char str[40];
1382 (void) strcpy(str, "no error");
1385 (void) strcpy(str, "Not owner");
1388 (void) strcpy(str, "No such file or directory");
1391 (void) strcpy(str, "I/O error");
1394 (void) strcpy(str, "No such device or address");
1397 (void) strcpy(str, "Permission denied");
1400 (void) strcpy(str, "File exists");
1403 (void) strcpy(str, "Cross-device link");
1406 (void) strcpy(str, "No such device");
1408 case NFS3ERR_NOTDIR:
1409 (void) strcpy(str, "Not a directory");
1412 (void) strcpy(str, "Is a directory");
1415 (void) strcpy(str, "Invalid argument");
1418 (void) strcpy(str, "File too large");
1421 (void) strcpy(str, "No space left on device");
1424 (void) strcpy(str, "Read-only file system");
1427 (void) strcpy(str, "Too many links");
1429 case NFS3ERR_NAMETOOLONG:
1430 (void) strcpy(str, "File name too long");
1432 case NFS3ERR_NOTEMPTY:
1433 (void) strcpy(str, "Directory not empty");
1436 (void) strcpy(str, "Disc quota exceeded");
1439 (void) strcpy(str, "Stale NFS file handle");
1441 case NFS3ERR_REMOTE:
1442 (void) strcpy(str, "Object is remote");
1444 case NFS3ERR_BADHANDLE:
1445 (void) strcpy(str, "Bad file handle");
1447 case NFS3ERR_NOT_SYNC:
1448 (void) strcpy(str, "Not sync write");
1450 case NFS3ERR_BAD_COOKIE:
1451 (void) strcpy(str, "Bad cookie");
1453 case NFS3ERR_NOTSUPP:
1454 (void) strcpy(str, "Operation not supported");
1456 case NFS3ERR_TOOSMALL:
1457 (void) strcpy(str, "Value too small");
1459 case NFS3ERR_SERVERFAULT:
1460 (void) strcpy(str, "Server fault");
1462 case NFS3ERR_BADTYPE:
1463 (void) strcpy(str, "Bad type");
1465 case NFS3ERR_JUKEBOX:
1466 (void) strcpy(str, "Jukebox");
1468 case NFS3ERR_RFS_TIMEOUT:
1469 (void) strcpy(str, "Timeout");
1472 (void) sprintf(str, "Unknown status %d", status);
1479 * Check the gettimeofday() resolution. If the resolution
1480 * is in chunks bigger than SFS_MIN_RES then the client
1481 * does not have a usable resolution for running the
1488 char tmp_hostname[HOSTNAME_LEN];
1490 time_res = get_resolution();
1491 getmyhostname(tmp_hostname, HOSTNAME_LEN);
1492 if( time_res > (double)SFS_MIN_RES )
1494 (void) fprintf(stderr,
1495 "\n%s: Clock resolution too poor to obtain valid results.\n",
1497 (void) fprintf(stderr,
1498 "%s: Clock resolution %f Micro seconds.\n", tmp_hostname,
1504 (void) fprintf(stderr,
1505 "\n%s: Good clock resolution [ %f ] Micro seconds.\n",
1506 tmp_hostname, time_res);
1511 * Lifted code from Iozone with permission from author. (Don Capps)
1512 * Returns the resolution of the gettimeofday() function
1516 get_resolution(void)
1518 double starttime, finishtime, besttime;
1522 finishtime=time_so_far1(); /* Warm up the instruction cache */
1523 starttime=time_so_far1(); /* Warm up the instruction cache */
1524 delay=j=0; /* Warm up the data cache */
1529 starttime=time_so_far1();
1530 for(j=0;j< delay;j++)
1532 finishtime=time_so_far1();
1533 if(starttime==finishtime)
1538 besttime=(finishtime-starttime);
1539 if((finishtime-starttime) < besttime)
1540 besttime=(finishtime-starttime);
1549 * Lifted code from Iozone with permission from author. (Don Capps)
1550 * Returns current result of gettimeofday() in microseconds.
1552 /************************************************************************/
1553 /* Time measurement routines. */
1554 /* Return time in microseconds */
1555 /************************************************************************/
1560 /* For Windows the time_of_day() is useless. It increments in 55 */
1561 /* milli second increments. By using the Win32api one can get */
1562 /* access to the high performance measurement interfaces. */
1563 /* With this one can get back into the 8 to 9 microsecond */
1566 LARGE_INTEGER freq,counter;
1570 QueryPerformanceFrequency(&freq);
1571 QueryPerformanceCounter(&counter);
1572 bigcounter=(double)counter.HighPart *(double)0xffffffff +
1573 (double)counter.LowPart;
1574 wintime = (double)(bigcounter/(double)freq.LowPart);
1575 return((double)wintime*1000000.0);
1577 #if defined (OSFV4) || defined(OSFV3) || defined(OSFV5)
1580 if (getclock(TIMEOFDAY, (struct timespec *) &gp) == -1)
1582 return (( (double) (gp.tv_sec)*1000000.0) +
1583 ( ((float)(gp.tv_nsec)) * 0.001 ));
1587 if (gettimeofday(&tp, (struct timezone *) NULL) == -1)
1588 perror("gettimeofday");
1589 return ((double) (tp.tv_sec)*1000000.0) +
1590 (((double) tp.tv_usec) );
1598 fprintf(stderr, "trace play usage");
1600 extern void init_file_system (void)
1605 extern void init_dep_tab (void)
1608 memset (&dep_tab, 0, sizeof(dep_tab));
1610 dep_tab[0].disk_index = 0;
1611 dep_tab[1].disk_index = 2;
1612 dep_tab[2].disk_index = 3;
1613 dep_tab[3].disk_index = 5;
1614 dep_tab[4].disk_index = 7;
1615 dep_tab[5].disk_index = 9;
1616 dep_tab[6].disk_index = 11;
1617 dep_tab[7].disk_index = 12;
1618 dep_tab[8].disk_index = 15;
1619 dep_tab[9].disk_index = 17;
1620 dep_tab[10].disk_index = 18;
1621 dep_tab[11].disk_index = 20;
1627 extern void init_dep_tab_old (void)
1631 Cur_file_ptr = &Export_dir;
1634 for (i=0; i<5; i++) {
1635 dep_tab[i].flag = DEP_FLAG_INIT;
1636 dep_tab[i].proc = CREATE;
1637 dep_tab[i].timestamp.tv_sec = trace_starttime.sec;
1638 dep_tab[i].timestamp.tv_usec = trace_starttime.usec+i*10;
1639 dep_tab[i].init_dep_num = 0;
1640 dep_tab[i].cur_dep_num = 0;
1643 for (i=5; i<10; i++) {
1644 dep_tab[i].flag = DEP_FLAG_INIT;
1645 dep_tab[i].proc = CREATE;
1646 dep_tab[i].timestamp.tv_sec = trace_starttime.sec+i;
1647 dep_tab[i].timestamp.tv_usec = trace_starttime.usec;
1648 dep_tab[i].init_dep_num = 0;
1649 dep_tab[i].cur_dep_num = 0;
1652 dep_tab[2].init_dep_num = 2;
1653 dep_tab[2].cur_dep_num = 2;
1654 dep_tab[2].dep_ops[0] = 0;
1655 dep_tab[2].dep_ops[1] = 1;
1657 // printf ("trace_starttime (%d %d)\n", trace_starttime.sec, trace_starttime.usec);
1660 for (i=2; i<4; i++) {
1661 dep_tab[i].flag = DEP_FLAG_INIT;
1662 dep_tab[i].proc = CREATE;
1663 dep_tab[i].timestamp.tv_sec = trace_starttime.sec+i*10;
1664 dep_tab[i].timestamp.tv_usec = trace_starttime.usec;
1665 dep_tab[i].init_dep_num = 0;
1666 dep_tab[i].cur_dep_num = 0;
1672 for (i=0; i<dep_tab_size; i++)
1674 printf("dep_tab[%d].timestamp (%d %d)\n", i, dep_tab[i].timestamp.tv_sec, dep_tab[i].timestamp.tv_usec);
1678 void show_fhandle (nfs_fh3 * fhp)
1680 struct knfs_fh * kfhp = (struct knfs_fh *)fhp;
1687 RFS_ASSERT (kfhp->fh_version == 1);
1688 RFS_ASSERT (kfhp->fh_fsid_type == 0);
1689 RFS_ASSERT (kfhp->fh_auth_type == 0);
1691 dev = ntohs(kfhp->fh_dev_major);
1693 dev = dev + ntohs(kfhp->fh_dev_minor);
1695 /* kfhp->fh_dev_ino hold the inode number of export point of the mounted
1696 * file system. For example, if /tmp/t1 is exported, /tmp/t1/t2 is mounted,
1697 * then fh_dev_ino hold the inode number of t1, not t2
1700 switch (kfhp->fh_fileid_type) {
1702 printf("fh:type 0 root dev 0x%x dev_ino %d\n", dev, kfhp->fh_dev_ino);
1705 printf("fh:type 1 %d %x dev %x dev_ino %x\n",
1706 kfhp->fh_ino, kfhp->fh_generation, dev, kfhp->fh_dev_ino);
1709 printf("fh:type2 %d %x dirino %d dev 0x%x dev_ino %x\n",
1710 kfhp->fh_ino, kfhp->fh_generation, kfhp->fh_dirino, dev, kfhp->fh_dev_ino);
1717 nfs_fh3 zero_fhandle;
1720 memset (fh_map, 0, sizeof (fh_map));
1721 memset(fh_htable, 0, sizeof (fh_htable));
1722 memset (&zero_fhandle, 0, sizeof(nfs_fh3));
1723 printf ("SIZE of fh map %d KB\n", sizeof (fh_map)/1000);
1727 int add_fh (int map_flag, char * trace_fh, char * path, nfs_fh3 * play_fh)
1729 char * old_trace_fh;
1731 /* first lookup if the entry for fh is already in the table */
1732 struct generic_entry * p;
1734 p = generic_lookup (trace_fh, TRACE_FH_SIZE, 0, fh_htable, FH_HTABLE_SIZE);
1736 RFS_ASSERT (fh_map[p->key3].flag = FH_MAP_FLAG_PARTIAL);
1737 RFS_ASSERT (map_flag ==FH_MAP_FLAG_COMPLETE);
1738 fh_map[p->key3].flag = map_flag;
1739 //RFS_ASSERT (!memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE));
1740 if (memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE)) {
1742 printf ("fh_map[%d].trace_fh %s trace_fh %s", p->key3, fh_map[p->key3].trace_fh, trace_fh);
1743 for (i=0; i<fh_i; i++) {
1744 int * p1 = (int *)&(fh_map[i].play_fh);
1745 #ifdef COMPRESS_TRACE_FH
1746 int * p = (int *)fh_map[i].trace_fh;
1747 printf("fh_map[%d].trace_fh %8x%8x%8x%8x%8x%8x%8x%8x path %s \nnew_filehandle %8x%8x%8x%8x%8x%8x%8x%8x\n",
1748 i, *p, *(p+1), *(p+2), *(p+3), *(p+4), *(p+5), *(p+6), *(p+7), fh_map[i].path,
1749 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
1751 printf("fh_map[%d].trace_fh %s path %s \nnew_filehandle %8x%8x%8x%8x%8x%8x%8x%8x\n",
1752 i, fh_map[i].trace_fh, fh_map[i].path,
1753 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
1758 RFS_ASSERT (!strcmp(fh_map[p->key3].path, path));
1759 /* It's possible that in fh-path-map, many trace_fh are corresponding to one path
1760 * some of it may be the result of lookup after symlink, which is not handled
1761 * properly as new created objects
1763 #ifdef TAKE_CARE_SYMBOLIC_LINK
1764 RFS_ASSERT (!memcmp(&fh_map[p->key3].play_fh, &zero_fhandle, sizeof(nfs_fh3)));
1766 memcpy (&fh_map[p->key3].play_fh, play_fh, sizeof (nfs_fh3));
1767 if ((fh_map_debug==1)) // || (stage ==TRACE_PLAY_STAGE))
1768 printf ("update the play_fh for trace_fh %s path %s \n", trace_fh, path);
1772 fh_map[fh_i].flag = map_flag;
1773 fh_map[fh_i].lock = 0;
1774 strncpy(fh_map[fh_i].trace_fh, trace_fh, TRACE_FH_SIZE);
1776 RFS_ASSERT (strlen(path) < MAX_PLAY_PATH_SIZE);
1777 strcpy (fh_map [fh_i].path, path);
1778 if (map_flag==FH_MAP_FLAG_COMPLETE)
1779 memcpy (&fh_map[fh_i].play_fh, play_fh, sizeof(nfs_fh3));
1781 memset (&fh_map[fh_i].play_fh, 0, sizeof(nfs_fh3));
1783 if ((fh_map_debug==1)) { // || (stage ==TRACE_PLAY_STAGE)) {
1784 printf ("insert trace_fh %s path %s play_fh:\n", trace_fh, path);
1785 if (map_flag == FH_MAP_FLAG_COMPLETE) {
1786 //show_fhandle(play_fh);
1792 if (map_flag == FH_MAP_FLAG_DISCARD)
1793 printf ("insert flag %d trace_fh %s path %s play_fh:\n", map_flag, trace_fh, path);
1796 generic_insert(trace_fh, TRACE_FH_SIZE, fh_i, fh_htable, FH_HTABLE_SIZE);
1799 RFS_ASSERT (fh_i < FH_MAP_SIZE);
1804 inline fh_map_t * lookup_fh (char * trace_fh )
1806 struct generic_entry * p;
1807 p = generic_lookup (trace_fh, TRACE_FH_SIZE, 0, fh_htable, FH_HTABLE_SIZE);
1808 if (fh_map_debug==1)
1809 printf ("lookup trace_fh %s\n", trace_fh);
1812 if (fh_map_debug==1) {
1813 printf ("found: fh_i[%d] trace_fh %s path %s play_fh:\n", p->key3, fh_map[p->key3].trace_fh, fh_map[p->key3].path);
1814 //show_fhandle(&fh_map[p->key3].play_fh);
1816 RFS_ASSERT (!memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE));
1817 return (&(fh_map[p->key3]));
1819 //printf ("lookup_fh %s not found\n", trace_fh);
1820 if (stage != READ_DEP_TAB_STAGE && (fh_map_debug==1)) {
1821 printf ("lookup not found trace_fh %s\n", trace_fh);
1828 int delete_fh (char * trace_fh, int fh_map_index)
1830 generic_delete (trace_fh, TRACE_FH_SIZE, fh_map_index, fh_htable, FH_HTABLE_SIZE);
1834 void lookup_init_filesystem (nfs_fh3 * parent, char * name, nfs_fh3 * result)
1837 LOOKUP3res reply; /* the reply */
1838 enum clnt_stat rpc_stat; /* result from RPC call */
1839 struct ladtime start;
1840 struct ladtime stop;
1843 /* set up the arguments */
1844 (void) memcpy((char *) &args.what.dir, (char *) parent,
1846 args.what.name = name;
1847 (void) memset((char *) &reply.resok.object, '\0', sizeof (nfs_fh3));
1850 sfs_gettime(&start);
1851 rpc_stat = clnt_call(NFS_client, NFSPROC3_LOOKUP,
1852 xdr_LOOKUP3args, (char *) &args,
1853 xdr_LOOKUP3res, (char *) &reply,
1857 if (rpc_stat !=RPC_SUCCESS) {
1858 printf("rpc_stat %d\n", rpc_stat);
1861 RFS_ASSERT (rpc_stat == RPC_SUCCESS);
1862 RFS_ASSERT (reply.status == NFS3_OK);
1863 (void) memcpy((char *) result, (char *) &reply.resok.object, sizeof (nfs_fh3));
1866 void read_fh_map(char * fh_map_file)
1871 char trace_fh[TRACE_FH_SIZE];
1876 #define MAX_PATH_DEPTH 20
1877 nfs_fh3 parents[MAX_PATH_DEPTH];
1878 char * lookup_path_ptr[MAX_PATH_DEPTH];
1879 char lookup_path [MAX_PLAY_PATH_SIZE];
1881 int new_dir_flag = 0;
1884 memset(lookup_path_ptr, 0, sizeof(lookup_path_ptr));
1885 memcpy(&parents[depth], &(Export_dir.fh_data->sfs_fh_un.f_fh3), sizeof(nfs_fh3));
1886 strcpy(lookup_path, "/");
1887 lookup_path_ptr[depth]=&lookup_path[0];
1889 fp = fopen(fh_map_file, "r");
1890 RFS_ASSERT (fp!=NULL);
1894 memset(buf, 0, sizeof(buf));
1895 while (fgets(buf, 1024, fp)) {
1897 if (fh_i % 10000==0)
1898 printf("%d fh_map entry read\n", fh_i);
1900 RFS_ASSERT (buf[strlen(buf)-1]=='\n');
1901 buf[strlen(buf)-1]=0;
1903 printf("%d fgets return %s\n", fh_i, buf);
1904 printf("depth %d lookup_path %s\n", depth, lookup_path);
1906 //for (i=0; i<=depth; i++)
1907 //printf("lookup_path_ptr[%d] %s ", i, lookup_path_ptr[i]);
1909 #ifdef COMPRESS_TRACE_FH
1910 for (i=0; i<TRACE_FH_SIZE/8; i++) {
1911 strncpy(intbuf, buf+i*8, 8);
1912 sscanf(intbuf, "%x", trace_fh+i*8); // maybe it should be 4, anyway we don't compress for now
1914 trace_path = buf+TRACE_FH_SIZE*2+1; /* +1 the trace contains only initial file handle */
1916 memcpy(trace_fh, buf, TRACE_FH_SIZE);
1917 trace_path = buf + TRACE_FH_SIZE +1;
1919 #ifdef TRACE_CONTAIN_LATER_FHANDLE
1920 trace_path = +=2; /* +3 if the trace contains both initial and later created file handle */
1923 #ifdef NO_DEPENDENCY_TABLE
1924 if (!strncmp (trace_path, "DISCARD", 7)) {
1925 map_flag = FH_MAP_FLAG_DISCARD;
1926 add_fh (map_flag, buf, trace_path, 0);
1931 p = trace_path+strlen(trace_path)-2;
1935 //RFS_ASSERT (p-trace_path<=strlen(lookup_path)+1);
1936 //RFS_ASSERT (p>trace_path);
1938 if (strncmp(lookup_path, trace_path, p-trace_path)) {
1939 printf("strncmp lookup_path %s trace_path %s for length %d\n", lookup_path, trace_path, p-trace_path);
1941 RFS_ASSERT (!strncmp(lookup_path, trace_path, p-trace_path));
1942 //while (strncmp(lookup_path, trace_path, p-trace_path)) { /* one step deeper */
1943 while (strlen(lookup_path)>p-trace_path && depth>0) {
1944 //printf("depth--\n");
1946 printf ("lookup_path %s trace_path %s p-trace_path %d depth %d\n", lookup_path, trace_path, p-trace_path, depth);
1947 RFS_ASSERT (depth>0);
1948 *lookup_path_ptr[depth]=0;
1949 lookup_path_ptr[depth]=0;
1952 RFS_ASSERT (strlen(lookup_path)==(p-trace_path) || (depth==0));
1955 #ifdef TRACE_CONTAIN_LATER_FHANDLE
1956 if (buf[TRACE_FH_SIZE*2+1]=='Y') {
1957 map_flag = FH_MAP_FLAG_COMPLETE;
1959 map_flag = FH_MAP_FLAG_PARTIAL;
1960 RFS_ASSERT (buf[TRACE_FH_SIZE*2+1]=='N');
1963 map_flag = FH_MAP_FLAG_COMPLETE;
1965 if ((*(p+strlen(p)-1))=='/') {
1971 if (map_flag == FH_MAP_FLAG_COMPLETE) {
1972 lookup_init_filesystem (&parents[depth], p, &parents[depth+1]);
1973 add_fh (map_flag, buf, trace_path, &parents[depth+1]);
1975 add_fh (map_flag, buf, trace_path, 0);
1978 /* the new fhandle is of a directory */
1979 lookup_path_ptr[depth+1] = lookup_path+strlen(lookup_path);
1980 strcat (lookup_path, p);
1981 strcat (lookup_path, "/");
1983 //printf("depth++\n");
1987 memset(buf, 0, sizeof(buf));
1991 for (i=0; i<fh_i; i++) {
1992 int * p1 = (int *)&(fh_map[i].play_fh);
1993 #ifdef COMPRESS_TRACE_FH
1994 int * p = (int *)fh_map[i].trace_fh;
1995 printf("fh_map[%d].trace_fh %8x%8x%8x%8x%8x%8x%8x%8x path %s \nnew_filehandle %8x%8x%8x%8x%8x%8x%8x%8x\n",
1996 i, *p, *(p+1), *(p+2), *(p+3), *(p+4), *(p+5), *(p+6), *(p+7), fh_map[i].path,
1997 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
1999 printf("fh_map[%d].trace_fh %s path %s \nnew_filehandle %8x%8x%8x%8x%8x%8x%8x%8x\n",
2000 i, fh_map[i].trace_fh, fh_map[i].path,
2001 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
2005 fprintf(stderr, "total %d requests \n", i);
2014 inline void finish_request (int biod_index, int dep_index, int status)
2016 /* the ending operation, same as when a request time out */
2017 dep_tab[dep_index].stop = biod_reqp[biod_index].stop; /* RFS: to dump data */
2018 dep_tab[dep_index].status = status;
2019 event_order[event_order_index++] = -dep_index;
2020 biod_reqp[biod_index].in_use = FALSE;
2021 dep_tab[dep_index].flag = DEP_FLAG_DONE;
2022 if (is_dir_op(dep_tab[dep_index].proc)) {
2024 RFS_ASSERT (dep_tab[dep_index].fh->lock = 1);
2025 dep_tab[dep_index].fh->lock = 0;
2026 if (dep_tab[dep_index].proc==RENAME)
2027 dep_tab[dep_index].fh_2->lock = 0;
2028 j = dep_tab[dep_index].fh-fh_map;
2029 if (dependency_debug) {
2030 printf ("fh_map[%d] is UNlocked\n",j);
2031 printf ("trace_fh %d path %s\n", dep_tab[dep_index].fh->trace_fh, dep_tab[dep_index].fh->path);
2032 printf ("trace_fh %d path %s\n", fh_map[j].trace_fh, fh_map[j].path);
2038 /* the request argument may have pointers pointing to buffers, e.g. the name in lookup,
2039 * the target of symlink, the write data */
2040 char arg_res[MAX_ARG_RES_SIZE];
2041 int poll_timeout = 0; /* timeout in usecs */
2042 char buf1 [MAX_BUF1_SIZE];
2043 char buf2 [MAX_BUF2_SIZE];
2045 int execute_next_request ()
2050 struct biod_req * reqp;
2051 sfs_op_type *op_ptr; /* per operation info */
2052 struct ladtime call_timeout;
2054 start_profile (&valid_get_nextop_profile);
2055 start_profile (&invalid_get_nextop_profile);
2056 dep_index = get_nextop();
2057 if (dep_index == -1) {
2058 end_profile (&invalid_get_nextop_profile);
2061 end_profile (&valid_get_nextop_profile);
2063 start_profile (&prepare_argument_profile);
2064 line = dep_tab[dep_index].line;
2065 if ((dep_index%(10000))==0) {
2067 fprintf (stderr, "processing dep_tab[%d] disk_index %d num_out_reqs %d \n", dep_index, dep_tab[dep_index].disk_index, num_out_reqs);
2069 fprintf (stderr, "processing dep_tab[%d] disk_index %d num_out_reqs %d can_not_catch_speed_num %d PLAY_SCALE %d \n", dep_index, dep_tab[dep_index].disk_index, num_out_reqs, can_not_catch_speed_num, PLAY_SCALE);
2071 if (can_not_catch_speed_num < 2000) {
2073 printf ("set PLAY_SCALE to %d\n", PLAY_SCALE);
2075 if (can_not_catch_speed_num > 50000) {
2078 if (can_not_catch_speed_num > 5000) {
2085 can_not_catch_speed_num = 0;
2089 printf ("processing dep_tab[%d] disk_index %d %s\n", dep_index, dep_tab[dep_index].disk_index, line);
2091 proc = dep_tab[dep_index].proc;
2092 rfs_Ops[proc].setarg (dep_index, line, arg_res, buf1, buf2);
2094 op_ptr = &Ops[proc];
2095 reqp = get_biod_req (dep_index);
2098 call_timeout.sec = 2; //Nfs_timers[op_ptr->call_class].tv_sec;
2099 call_timeout.usec = Nfs_timers[op_ptr->call_class].tv_usec;
2102 sfs_gettime(&(reqp->start));
2103 end_profile (&prepare_argument_profile);
2104 start_profile (&biod_clnt_call_profile);
2107 reqp->xid = biod_clnt_call(NFS_client, rfs_Ops[proc].nfsv3_proc,
2108 rfs_Ops[proc].xdr_arg, arg_res);
2111 reqp->xid = dep_index+1; /* just fake a message id and let it expire */
2113 if (reqp->xid != 0) {
2114 reqp->timeout = reqp->start;
2115 ADDTIME (reqp->timeout, call_timeout);
2117 dep_tab[dep_index].flag = DEP_FLAG_SENT;
2118 event_order[event_order_index++] = dep_index;
2122 dep_tab[dep_index].start = reqp->start; /* RFS: to dump data */
2123 end_profile (&biod_clnt_call_profile);
2126 inline void check_reply (int proc, int biod_index, int dep_index, int status, char * errmsg, int trace_status)
2128 if (((status!=trace_status)) && (trace_status!=NFS3ERR_RFS_MISS)) {
2130 printf ("receive problem reply, xid %x nfs_ret %d %s trace_status %d start %d:%d stop %d:%d command disk index %d\n", biod_reqp[biod_index].xid, status, errmsg, trace_status, biod_reqp[biod_index].start.sec, biod_reqp[biod_index].start.usec, biod_reqp[biod_index].stop.sec, biod_reqp[biod_index].stop.usec, dep_tab[dep_index].disk_index);
2131 #ifndef TAKE_CARE_UNLOOKED_UP_NON_NEW_FILES
2132 /* these files is not looked up and is not create/mkdir/symlink/link/mknod ed before they
2133 * are refered by name through rename, remove
2135 if ((proc==RENAME || proc==REMOVE) && (status==NFS3ERR_NOENT) && (trace_status ==0)) {
2136 /* current initialization doesnot take care of rename source, if there is no
2137 * create or lookup before that source, the source object will not exist when
2140 rename_rmdir_noent_reply_num++;
2143 #ifndef TAKE_CARE_SYMBOLIC_LINK
2144 if ((proc==LOOKUP) && (status==NFS3_OK) && (trace_status==NFS3ERR_NOENT)) {
2145 /* in the original trace, first lookup return NOENT, then symlink is executed, then lookup return OK
2146 * the initialization considers only the lookup return OK and created the file in the initialization
2147 * so in trace play the first lookup return OK
2150 } else if ((proc==SYMLINK) && (status == NFS3ERR_EXIST) && (trace_status == 0)) {
2151 /* due to similar reason as above, the initialization code initializes the symbolic link as a normal
2157 #ifndef TAKE_CARE_NOEMPTY_RMDIR
2158 /* the remove packet seems got lost in the trace capture, so replay can not finish */
2159 if ((proc==RMDIR) && (status==NFS3ERR_NOTEMPTY)) {
2161 RENAME3res reply; /* the reply */
2162 RMDIR3args * rmdir_argp;
2163 enum clnt_stat rpc_stat; /* result from RPC call */
2165 rfs_Ops[proc].setarg (dep_index, dep_tab[dep_index].line, arg_res, buf1, buf2);
2166 rmdir_argp = (RMDIR3args *)arg_res;
2168 memcpy(&args.from, &(rmdir_argp->object), sizeof (diropargs3));
2169 memcpy(&args.to.dir, &(Export_dir.fh_data->sfs_fh_un.f_fh3), sizeof(nfs_fh3));
2170 args.from.name = buf1; /* the buf1 is already filled when parsing rmdir */
2171 args.to.name = buf2;
2172 sprintf(buf2, "rmdir_%d_%s", dep_tab[dep_index].disk_index, rmdir_argp->object.name);
2174 rpc_stat = clnt_call(NFS_client, NFSPROC3_RENAME,
2175 xdr_RENAME3args, (char *) &args,
2176 xdr_RENAME3res, (char *) &reply,
2178 RFS_ASSERT (rpc_stat == RPC_SUCCESS);
2179 if (reply.status!=NFS3_OK)
2180 printf ("change rmdir into rename, reply.status %d\n", reply.status);
2181 RFS_ASSERT (reply.status==NFS3_OK);
2182 rmdir_not_empty_reply_num ++;
2184 #ifndef TAKE_CARE_ACCESS_ERROR
2185 } else if ((status==0) && (trace_status==NFS3ERR_ACCES)) {
2186 loose_access_control_reply_num ++;
2188 #ifdef NO_DEPENDENCY_TABLE
2189 } else if ((proc==LOOKUP) && (status==NFS3ERR_NOENT) && (trace_status==NFS3_OK)) {
2190 lookup_err_due_to_rename_num ++;
2192 #ifndef TAKE_CARE_LOOKUP_EACCESS_ENOENT_MISMATCH
2193 /* if the looked return EACCESS in the trace, means the object still exists
2194 * should have initialized, right not don't initialize it, hence play status
2197 } else if ((proc==LOOKUP) && (status==NFS3ERR_NOENT) && (trace_status==NFS3ERR_ACCES)) {
2198 lookup_eaccess_enoent_mismatch_num ++;
2200 #ifdef TOLERANT_READ_IO_ERR
2201 } else if ((proc==READ) && (status==NFS3ERR_IO) && (trace_status==NFS3_OK)) {
2206 for (i=min_dep_index; i<max_dep_index; i++)
2207 printf ("dep_tab[%d].disk_index %d, flag %d line %s\n", i, dep_tab[i].disk_index, dep_tab[i].flag, dep_tab[i].line);
2211 proper_reply_num ++;
2215 /* return -1 if there is no reply being received
2216 * return the dep_index if the corresponding reply has been received
2218 inline int receive_next_reply (int busy_flag)
2225 sfs_op_type *op_ptr; /* per operation info */
2231 /* wait for reply */
2232 start_profile (&valid_poll_and_get_reply_profile);
2233 start_profile (&invalid_poll_and_get_reply_profile);
2235 if (busy_flag == BUSY) {
2237 poll_timeout_0_num ++;
2239 poll_timeout = 10000; /* 10000 or 2000 is a better number in non-debugging state */
2240 poll_timeout_pos_num ++;
2243 biod_index = poll_and_get_reply (poll_timeout);
2244 if (biod_index==-1) {
2245 end_profile (&invalid_poll_and_get_reply_profile);
2248 end_profile (&valid_poll_and_get_reply_profile);
2250 start_profile (&decode_reply_profile);
2251 /* check the corresponding request */
2252 dep_index = biod_reqp[biod_index].dep_tab_index;
2253 proc = dep_tab[dep_index].proc;
2254 op_ptr = &Ops[proc];
2256 if (dep_tab[dep_index].flag != DEP_FLAG_SENT) {
2257 printf("dep_tab[%d].flag %d proc %d status %d start %d:%d stop %d:%d\n",
2258 dep_index, dep_tab[dep_index].flag, proc, dep_tab[dep_index].status,
2259 dep_tab[dep_index].start.sec, dep_tab[dep_index].start.usec,
2260 dep_tab[dep_index].stop.sec, dep_tab[dep_index].stop.usec );
2261 printf ("received reply for timeout requests dep_tab[%d].disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
2264 RFS_ASSERT (dep_tab[dep_index].flag == DEP_FLAG_SENT);
2266 /* decode the reply */
2267 rfs_Ops[proc].setres (arg_res, buf1);
2268 ret = proc_header (NFS_client, rfs_Ops[proc].xdr_res, arg_res);
2269 RFS_ASSERT (ret == RPC_SUCCESS);
2270 status = *((int *)arg_res);
2271 errmsg = nfs3_strerror (status);
2272 end_profile (&decode_reply_profile);
2274 start_profile (&check_reply_profile);
2275 /* compare with the reply in the trace */
2276 line = dep_tab[dep_index].line;
2277 reply_line = dep_tab[dep_index].reply_line;
2278 trace_status = dep_tab[dep_index].trace_status;
2280 /* print the result, trace play progress indicator */
2281 if (rfs_debug || ( !profile_debug && ((dep_index %10000)==0) ) )
2282 fprintf (stdout, "dep_tab[%d], disk_index %d, receive reply, rpc_ret %d xid %x nfs_ret %d %s trace_status %d start %d:%d stop %d:%d \n", dep_index, dep_tab[dep_index].disk_index, ret, biod_reqp[biod_index].xid, status, errmsg, trace_status, biod_reqp[biod_index].start.sec, biod_reqp[biod_index].start.usec, biod_reqp[biod_index].stop.sec, biod_reqp[biod_index].stop.usec);
2284 /* error checking */
2285 check_reply (proc, biod_index, dep_index, status, errmsg, trace_status);
2287 /* free resources */
2288 finish_request (biod_index, dep_index, status);
2290 /* get statistics */
2291 if (status == trace_status) {
2292 op_ptr->results.good_calls++;
2293 Ops[TOTAL].results.good_calls++;
2295 op_ptr->results.bad_calls++;
2296 Ops[TOTAL].results.bad_calls++;
2298 sfs_elapsedtime (op_ptr, &(biod_reqp[biod_index].start), &(biod_reqp[biod_index].stop));
2299 end_profile (&check_reply_profile);
2301 //start_profile (&add_create_object_profile);
2303 #ifndef TAKE_CARE_SYMBOLIC_LINK
2304 if (trace_status == NFS3_OK && (proc==CREATE || proc==MKDIR || proc==MKNOD)) {
2308 if (trace_status == NFS3_OK && (proc==CREATE || proc==MKDIR || proc==SYMLINK || proc==MKNOD)) {
2309 RFS_ASSERT (reply_line);
2310 if (status!=NFS3_OK) {
2311 RFS_ASSERT (proc==SYMLINK);
2313 if (proc!=SYMLINK || line[TRACE_VERSION_POS]!='2')
2314 add_new_file_system_object(proc, dep_index, line, reply_line);
2317 //end_profile (&add_create_object_profile);
2320 inline void add_new_file_system_object (int proc, int dep_index, char * line, char * reply_line)
2322 char * child_trace_fh;
2323 fh_map_t * parent_entryp;
2324 char component_name[MAX_PLAY_PATH_SIZE];
2325 char * parent_trace_fh;
2326 char child_path[MAX_PLAY_PATH_SIZE];
2327 post_op_fh3 * post_op_fh3_child;
2328 char * reply_trace_fh;
2329 nfs_fh3 * child_fh3;
2331 parent_trace_fh = strstr (line, "fh");
2332 RFS_ASSERT (parent_trace_fh);
2333 parent_trace_fh +=3;
2334 parent_entryp = lookup_fh (parent_trace_fh);
2335 RFS_ASSERT (parent_entryp);
2336 parse_name (parent_trace_fh+65, component_name);
2337 strcpy (child_path, parent_entryp->path);
2338 strcat (child_path, "/");
2339 strcat (child_path, component_name);
2341 /* find the corresponding create request */
2342 //printf ("before find reply trace_fh reply_line %s\n", reply_line);
2343 reply_trace_fh = find_reply_trace_fh (reply_line);
2344 RFS_ASSERT (reply_trace_fh != NULL);
2347 RFS_ASSERT (((CREATE3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
2348 child_fh3 = &((CREATE3res *)arg_res)->res_u.ok.obj.handle;
2351 RFS_ASSERT (((MKDIR3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
2352 child_fh3 = &((MKDIR3res *)arg_res)->res_u.ok.obj.handle;
2355 RFS_ASSERT (((SYMLINK3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
2356 child_fh3 = &((SYMLINK3res *)arg_res)->res_u.ok.obj.handle;
2359 RFS_ASSERT (((MKNOD3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
2360 child_fh3 = &((MKNOD3res *)arg_res)->res_u.ok.obj.handle;
2363 RFS_ASSERT (proc==LOOKUP);
2364 child_fh3 = &((LOOKUP3res *)arg_res)->res_u.ok.object;
2369 RFS_ASSERT (reply_trace_fh[TRACE_FH_SIZE]==' ');
2370 reply_trace_fh[TRACE_FH_SIZE] = 0;
2371 add_fh (FH_MAP_FLAG_COMPLETE, reply_trace_fh, child_path, child_fh3); /* exist flag is not used now, set to 1 */
2372 reply_trace_fh[TRACE_FH_SIZE] = ' ';
2375 /* initialize timestamp and proc field of dep_tab entry */
2376 void trace_play(void)
2379 /* The flag to indicate whether trace_player is BUSY. Trace_player is BUSY
2380 * when either there is request to send or there is reply being
2381 * received. Otherwise it is IDLE. The timeout for polling replies
2382 * is set to 0 when BUSY, it is set to the waiting time to the first
2383 * request outside of current <min_dep_index, max_dep_index> window when IDLE.
2385 int busy_flag = BUSY;
2387 //int dep_index; /* index into dependency table: dep_tab */
2388 //int biod_index; /* index into outstanding requests: biod_reqp */
2393 adjust_play_window(busy_flag, &poll_timeout);
2395 start_profile (&total_profile);
2396 while ((min_dep_index<dep_tab_size) || (num_out_reqs>0)) {
2398 if (busy_flag == IDLE) {
2399 //start_profile (&check_timeout_profile);
2401 //end_profile (&check_timeout_profile);
2404 //start_profile (&adjust_play_window_profile);
2405 //adjust_play_window (flag, &poll_timeout);
2406 //adjust_play_window (flag+(max_dep_index-min_dep_index), &poll_timeout);
2407 adjust_play_window (busy_flag, &poll_timeout);
2409 printf("num_out_reqs %d\n", num_out_reqs);
2411 //end_profile (&adjust_play_window_profile);
2413 start_profile (&execute_next_request_profile);
2414 while (execute_next_request()!=-1)
2416 end_profile (&execute_next_request_profile);
2418 start_profile (&receive_next_reply_profile);
2419 /* actually the performance of two policy seems to be same */
2420 //#define SEND_HIGHER_PRIORITY_POLICY
2421 #define SEND_RECEIVE_EQUAL_PRIORITY_POLICY
2423 #ifdef SEND_HIGHER_PRIORITY_POLICY
2424 receive_next_reply(IDLE);
2426 #ifdef SEND_RECEIVE_EQUAL_PRIORITY_POLICY
2428 while (receive_next_reply(busy_flag)!=-1)
2431 end_profile (&receive_next_reply_profile);
2433 end_profile (&total_profile);
2435 print_profile ("total_profile", &total_profile);
2437 //print_profile ("check_timeout", &check_timeout_profile);
2439 //print_profile ("adjust_play_window", &adjust_play_window_profile);
2441 print_profile ("execute_next_request_profile", &execute_next_request_profile);
2442 print_profile ("valid_get_nextop_profile", &valid_get_nextop_profile);
2443 print_profile ("invalid_get_nextop_profile", &invalid_get_nextop_profile);
2444 print_profile ("prepare_argument", &prepare_argument_profile);
2445 print_profile ("biod_clnt_call", &biod_clnt_call_profile);
2447 print_profile ("receive_next_reply", &receive_next_reply_profile);
2448 print_profile ("valid_poll_and_get_reply_profile", &valid_poll_and_get_reply_profile);
2449 print_profile ("invalid_poll_and_get_reply_profile", &invalid_poll_and_get_reply_profile);
2450 print_profile ("decode_reply", &decode_reply_profile);
2451 print_profile ("check_reply", &check_reply_profile);
2452 //print_profile ("add_create_object", &add_create_object_profile);
2455 printf ("min_dep_index %d dep_tab_size %d num_out_reqs %d\n", min_dep_index, dep_tab_size, num_out_reqs);