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
106 * ----------------------- External Definitions -----------------------
108 extern uint32_t biod_clnt_call(CLIENT *, uint32_t, xdrproc_t, void *);
109 extern enum clnt_stat proc_header(CLIENT *cl, xdrproc_t xdr_results, void *results_ptr);
110 extern int biod_poll_wait(CLIENT *, uint32_t);
111 extern enum clnt_stat get_areply_udp (CLIENT * cl, uint32_t *xid, struct timeval *timeout);
112 extern char * parse_name (char * t, char * buf);
114 /* forward definitions for local functions */
115 static int init_rpc(void);
117 /* RFS: forward definitions for local functions */
119 static void init_signal();
120 extern void init_file_system (void);
121 extern void init_dep_tab (void);
122 static int read_trace(void);
123 static void read_fh_map();
124 static void init_play (char * mount_point);
125 static void trace_play(void);
126 void print_result(void);
127 static int get_nextop(void);
128 static int check_timeout(void);
129 static struct biod_req * get_biod_req(int dep_tab_index);
130 static int lookup_biod_req (int xid);
131 static void init_time_offset(void);
132 void adjust_play_window (int flag, int * poll_timeout);
133 static int poll_and_get_reply (int usecs);
134 static char * nfs3_strerror(int status);
135 static void check_clock(void);
136 static double time_so_far1(void);
137 static double get_resolution(void);
138 static void usage(void);
139 void init_dep_tab_entry (int dep_index);
140 extern inline fh_map_t * lookup_fh (char * trace_fh );
141 static inline void finish_request (int biod_index, int dep_index, int status);
142 static inline void add_new_file_system_object (int proc, int dep_index, char * line, char * reply_line);
143 static inline char * find_lead_trace_fh(int proc, char * line);
144 static inline char * find_reply_trace_fh (char * line);
147 * ------------- Per Child Load Generation Rate Variables -----------
149 static uint_t Calls_this_period; /* calls made during the current run period */
150 static uint_t Calls_this_test; /* calls made during the test so far */
151 static uint_t Reqs_this_period; /* reqs made during the current run period */
152 static uint_t Reqs_this_test; /* reqs made during the test so far */
153 static uint_t Sleep_msec_this_test; /* msec slept during the test so far */
154 static uint_t Sleep_msec_this_period;
155 static uint_t Previous_chkpnt_msec; /* beginning time of current run period */
156 static int Target_sleep_mspc; /* targeted sleep time per call */
158 static char io_buf[BUFSIZ]; /* io buffer for print out messages */
161 int Log_fd; /* log fd */
162 char Logname[NFS_MAXNAMLEN]; /* child processes sync logfile */
163 int Validate = 0; /* fake variable */
164 int Child_num = 0; /* fake: child index */
165 int Tcp = 0; /* We implement UDP first */
166 int Client_num = 1; /* fake: number of client */
171 * ------------------------- SFS Child -------------------------
174 static int nfs2proc_to_rfsproc[18] = {0, 1, 2, 3, 4, 5, 6, 7, 8, 9,
175 10, 11, 12, 13, 14, 15, 16, 17};
176 static int nfs3proc_to_rfsproc[NFS3_PROCEDURE_COUNT] = {0, 1, 2, 4, 18, 5, 6, 8, 9, 14,
177 13, 21, 10, 15, 11, 12, 16, 23, 17, 20,
179 void print_usage(int pos, int argc, char ** argv)
182 printf("sfs3 hostname:mount_dir trace_file|stdin fh_map_file play_scale warmup_time(in seconds) \n");
183 printf("sfs3 -pair_trace trace_file\n");
184 printf("sfs3 -pair_write trace_file\n");
185 printf("sfs3 -help\n");
186 printf ("pos %d argc %d", pos, argc);
187 for (i=0; i<argc; i++) {
188 printf(" %s", argv[i]);
194 void print_cyclic_buffers ()
196 CYCLIC_PRINT(memory_trace_index);
197 CYCLIC_PRINT(dep_tab_index);
198 CYCLIC_PRINT(dep_window_index);
201 void add_to_dep_tab(int i)
204 fh_map_t * fh_map_entry;
207 trace_fh = strstr (memory_trace[i].line, "fh");
209 printf ("memory_trace[%d].line %s\n", i, memory_trace[i].line);
210 RFS_ASSERT (trace_fh);
212 fh_map_entry = lookup_fh (trace_fh);
213 if (fh_map_entry && (fh_map_entry->flag==FH_MAP_FLAG_DISCARD) ) {
214 req_num_with_discard_fh ++;
218 req_num_with_init_fh ++;
220 req_num_with_new_fh ++;
222 RFS_ASSERT (!CYCLIC_FULL(dep_tab_index));
223 ent = &(dep_tab[dep_tab_index.head]);
225 ent->disk_index = memory_trace[i].disk_index;
226 ent->memory_index = i;
227 #ifdef REDUCE_MEMORY_TRACE_SIZE
228 ent->trace_status = memory_trace[i].trace_status;
229 ent->reply_trace_fh = memory_trace[i].reply_trace_fh;
231 ent->line = memory_trace[i].line;
232 init_dep_tab_entry(dep_tab_index.head);
234 if (rfs_debug && (i%100000)==0)
235 printf ("dep_tab[%d].disk_index %d = memory_trace[%d].disk_index %d\n", dep_tab_index.head, ent->disk_index, i, memory_trace[i].disk_index);
236 CYCLIC_MOVE_HEAD(memory_trace_index);
237 CYCLIC_MOVE_HEAD(dep_tab_index);
240 void init_profile_variables ()
242 init_profile ("total_profile", &total_profile);
243 init_profile ("execute_next_request_profile", &execute_next_request_profile);
244 init_profile ("valid_get_nextop_profile", &valid_get_nextop_profile);
245 init_profile ("invalid_get_nextop_profile",&invalid_get_nextop_profile);
246 init_profile ("prepare_argument_profile", &prepare_argument_profile);
247 init_profile ("biod_clnt_call_profile", &biod_clnt_call_profile);
248 init_profile ("receive_next_reply_profile", &receive_next_reply_profile);
249 init_profile ("valid_poll_and_get_reply_profile", &valid_poll_and_get_reply_profile);
250 init_profile ("invalid_poll_and_get_reply_profile", &invalid_poll_and_get_reply_profile);
251 init_profile ("decode_reply_profile", &decode_reply_profile);
252 init_profile ("check_reply_profile", &check_reply_profile);
253 init_profile ("add_create_object_profile", &add_create_object_profile);
254 init_profile ("check_timeout_profile", &check_timeout_profile);
255 init_profile ("adjust_play_window_profile",&adjust_play_window_profile);
256 init_profile ("fgets_profile",&fgets_profile);
257 init_profile ("read_line_profile",&read_line_profile);
258 init_profile ("read_trace_profile",&read_trace_profile);
261 static char trace_file[256]="anon-lair62-011130-1200.txt";
262 int print_memory_usage()
264 printf("size of fh_map_t %d size of fh_map %d\n", sizeof(fh_map_t), sizeof(fh_map));
265 printf("sizeof dep_tab_t %d sizeof dep_tab %d\n", sizeof(dep_tab_t), sizeof(dep_tab));
266 printf("size of memory_trace_ent_t %d sizeof memory_trace %d\n", sizeof(memory_trace_ent_t), sizeof(memory_trace));
267 printf("size of CREATE3args %d\n", sizeof( CREATE3args));
268 printf("size of MKDIR3args %d\n", sizeof( MKDIR3args));
269 printf("size of READ3args %d\n", sizeof( READ3args));
270 printf("size of WRITE3args %d\n", sizeof( WRITE3args));
271 printf("size of RENAME3args %d\n", sizeof( RENAME3args));
272 printf("size of GETATTR3args %d\n", sizeof( GETATTR3args));
273 printf("size of SETATTR3args %d\n", sizeof( SETATTR3args));
274 printf("size of LINK3args %d\n", sizeof( LINK3args));
275 printf("size of SYMLINK3args %d\n", sizeof( SYMLINK3args));
276 printf("size of MKNOD3args %d\n", sizeof( MKNOD3args));
277 printf("size of RMDIR3args %d\n", sizeof( RMDIR3args));
278 printf("size of REMOVE3args %d\n", sizeof( REMOVE3args));
279 printf("size of LOOKUP3args %d\n", sizeof( LOOKUP3args));
280 printf("size of READDIR3args %d\n", sizeof( READDIR3args));
281 printf("size of READDIRPLUS3args %d\n", sizeof( READDIRPLUS3args));
282 printf("size of FSSTAT3args %d\n", sizeof( FSSTAT3args));
283 printf("size of FSINFO3args %d\n", sizeof( FSINFO3args));
284 printf("size of COMMIT3args %d\n", sizeof( COMMIT3args));
285 printf("size of ACCESS3args %d\n", sizeof( ACCESS3args));
286 printf("size of READLINK3args %d\n", sizeof( READLINK3args));
293 /* number of seconds the I/O thread pauses after each time trying to read the requests */
294 #define IO_THREAD_PAUSE_TIME 1
299 disk_io_status = read_trace ();
300 while (disk_io_status == TRACE_BUF_FULL) {
304 printf("&&&&&&&&&& io thread, sleep %d seconds\n", j/10);
307 disk_io_status = read_trace ();
308 //printf ("io_thread, after read_trace, disk_index %d\n", disk_index);
311 for (i=0; i<SEQUEN_READ_NUM; i++) {
312 add_to_dep_tab(CYCLIC_MINUS(memory_trace_index.head,1,memory_trace_index.size));
315 //printf ("***************** IO THREAD SLEEP 1 s\n");
316 //print_cyclic_buffers();
319 RFS_ASSERT (disk_io_status == TRACE_FILE_END);
325 struct timeval playstart_time, playend_time;
327 sleep (10); /* first let io_thread to run for a while */
329 printf ("trace_play\n");
331 gettimeofday(&playstart_time, NULL);
335 gettimeofday(&playend_time, NULL);
339 sec = playend_time.tv_sec - playstart_time.tv_sec;
340 usec = sec * 1000000 + (playend_time.tv_usec - playstart_time.tv_usec);
341 sec = usec / 1000000;
342 usec = usec % 1000000;
343 printf("Total play time: %d sec %d usec\n", sec, usec);
354 pthread_t io_thread_var;
355 pthread_t execute_thread_var;
357 ret = pthread_attr_init (&attr);
359 perror("pthread_attr_init attr");
362 ret = pthread_create (&(io_thread_var), &attr, &io_thread, (void *)&arg );
364 perror("io_pthread_attr_init");
369 ret = pthread_create (&(execute_thread_var), &attr, &execute_thread, (void *)&arg );
371 perror("io_pthread_attr_init");
379 CYCLIC_INIT("memory_trace_index",memory_trace_index,MAX_MEMORY_TRACE_LINES);
380 CYCLIC_INIT("dep_tab_index ",dep_tab_index,DEP_TAB_SIZE);
381 CYCLIC_INIT("dep_window_index ",dep_window_index,DEP_TAB_SIZE);
384 int main(int argc, char ** argv)
386 extern char * optarg;
388 struct timeval in={1000000, 100};
390 init_profile_variables();
391 if ((argc==1) || (argc==2 && !strcmp(argv[1],"-help"))) {
392 print_usage(0, argc, argv);
395 if (!strcmp(argv[1], "-pair_write")) {
397 strcpy(trace_file, argv[2]);
399 strcpy(trace_file, "stdin");
400 pair_write(trace_file);
403 if (!strcmp(argv[1], "-pair_trace")) {
405 strcpy(trace_file, argv[2]);
407 strcpy(trace_file, "stdin");
408 pair_trace(trace_file);
411 if (!strcmp(argv[1], "-check_aging")) {
413 print_usage(3, argc, argv);
416 strcpy(trace_file, argv[2]);
417 check_aging (trace_file);
420 if (!strcmp(argv[1], "-check_statistics")) {
422 print_usage(1, argc, argv);
425 strcpy(trace_file, argv[2]);
426 memset(fh_htable, 0, sizeof (fh_htable));
427 check_statistics (trace_file);
432 print_usage(2, argc, argv);
435 PLAY_SCALE = atoi (argv[4]);
436 RFS_ASSERT (PLAY_SCALE >=1 && PLAY_SCALE <=10000);
438 WARMUP_TIME = atoi (argv[5]);
439 RFS_ASSERT (WARMUP_TIME >=0 && WARMUP_TIME <=1000);
441 print_memory_usage();
443 getmyhostname(lad_hostname, HOSTNAME_LEN);
447 * Get the uid and gid information.
454 Nfs_timers = Nfs_udp_timers;
459 //init_play ("capella:/p5/RFSFS");
461 read_fh_map (argv[3]);
462 //read_fh_map ("fh-path-map-play");
463 strcpy(trace_file, argv[2]);
465 /* If ordered by TIMESTAMP,
466 * memory_trace_index.tail <= dep_tab_index.tail < dep_window_max <=
467 * dep_tab_index.head <= memory_trace_index.head
479 nfs_version = NFS_V3;
482 /* Set up the signal handlers for all signals */
485 #if (defined(_XOPEN_SOURCE) || defined(USE_POSIX_SIGNALS))
486 struct sigaction sig_act, old_sig_act;
488 /* use XOPEN signal handling */
490 sig_act.sa_handler = generic_catcher;
491 (void)sigemptyset(&sig_act.sa_mask);
492 sig_act.sa_flags = 0;
494 /* signals handlers for signals used by sfs */
495 sig_act.sa_handler = sfs_cleanup;
496 if (sigaction(SIGINT,&sig_act,&old_sig_act) == -1) {
497 perror("sigaction failed: SIGINT");
501 sig_act.sa_handler = sfs_cleanup;
502 if (sigaction(SIGTERM,&sig_act,&old_sig_act) != 0) {
503 perror("sigaction failed: SIGTERM");
507 /* signals handlers for signals used by sfs */
508 (void) signal(SIGINT, sfs_cleanup);
509 // RFS (void) signal(SIGALRM, sfs_alarm);
510 (void) signal(SIGTERM, sfs_cleanup);
516 char * mount_point) /* Mount point for remote FS */
518 char namebuf[NFS_MAXNAMLEN] = "trace_play"; /* unique name for this program */
519 CLIENT * mount_client_ptr; /* Mount client handle */
522 (void) setvbuf(stderr, io_buf, _IOLBF, BUFSIZ);
524 sfs_Myname = namebuf;
527 * May require root priv to perform bindresvport operation
529 mount_client_ptr = lad_getmnt_hand(mount_point);
530 if (mount_client_ptr == NULL) {
535 * should be all done doing priv port stuff
538 if (init_rpc() == -1) {
539 (void) fprintf(stderr, "%s: rpc initialization failed\n", sfs_Myname);
540 (void) generic_kill(0, SIGINT);
546 * finish all priv bindresvport calls
549 if (setuid(Real_uid) != (uid_t)0) {
550 (void) fprintf(stderr,"%s: %s%s", sfs_Myname,
551 "cannot perform setuid operation.\n",
552 "Do `make install` as root.\n");
555 init_mount_point(0, mount_point, mount_client_ptr);
559 * Cleanup client handle for mount point
561 clnt_destroy(mount_client_ptr);
566 #ifdef REDUCE_MEMORY_TRACE_SIZE
567 inline char * read_line (int disk_index)
569 static FILE * fp=NULL;
571 static int start_disk_index=0;
573 static int finish_flag = 0;
575 #define READ_LINE_BUF_SIZE (MAX_COMMAND_REPLY_DISTANCE_FOR_PAIR+2)
576 #define SAFE_BYTES 1000
577 #define READ_LINE_LENGTH (MAX_TRACE_LINE_LENGTH+SAFE_BYTES)
579 static char line_buf[READ_LINE_BUF_SIZE][READ_LINE_LENGTH];
580 start_profile (&read_line_profile);
583 if (strcmp(trace_file, "stdin")) {
584 fp = fopen(trace_file, "r");
586 printf("can not open files %s\n", fp);
592 RFS_ASSERT (fp!=NULL);
593 for (i=0; i<READ_LINE_BUF_SIZE; i++) {
594 start_profile(&fgets_profile);
595 if (!fgets(line_buf[i], READ_LINE_LENGTH, fp)) {
598 end_profile(&fgets_profile);
599 //printf ("read_line, line_buf[%d]:%s", i, line_buf[i]);
603 RFS_ASSERT (disk_index <= start_disk_index+READ_LINE_BUF_SIZE)
604 if (disk_index==(start_disk_index+READ_LINE_BUF_SIZE)) {
608 start_profile(&fgets_profile);
609 if (!fgets(line_buf[start], READ_LINE_LENGTH, fp)) {
610 end_profile(&fgets_profile);
614 end_profile(&fgets_profile);
615 //printf ("read_line, line_buf[%d]:%s", start, line_buf[start]);
616 start = (start+1) % READ_LINE_BUF_SIZE;
619 RFS_ASSERT (disk_index < start_disk_index+READ_LINE_BUF_SIZE)
620 i = (start+disk_index-start_disk_index)%READ_LINE_BUF_SIZE;
623 if (!(strlen(line_buf[i])>80)) {
624 printf ("start %d start_disk_index %d disk_index %d strlen %d line_buf[%d] %s\n", start, start_disk_index, disk_index, strlen(line_buf[i]), i, line_buf[i]);
625 RFS_ASSERT (strlen(line_buf[i])>80);
627 if (!((strlen(line_buf[i])>80) && (strlen(line_buf[i])<MAX_TRACE_LINE_LENGTH)))
628 printf ("disk_index %d strlen %d line_buf[%d] %s\n", disk_index, strlen(line_buf[i]), i, line_buf[i]);
629 RFS_ASSERT ((strlen(line_buf[i])>80) && (strlen(line_buf[i])<MAX_TRACE_LINE_LENGTH));
632 end_profile (&read_line_profile);
633 return (line_buf[i]);
636 #define OPS_FLAG_INC 0
637 #define OPS_FLAG_PRINT 1
638 int read_write_fh_statistics (int flag, char * buf, int timestamp)
640 static FILE * fp = NULL;
644 fp = fopen ("read_write_fh.output", "w");
647 if (flag == OPS_FLAG_INC) {
648 p = strstr (buf, "fh");
652 fprintf(fp, "%s\n", p+3+24);
655 if (flag == OPS_FLAG_PRINT) {
656 int disk_index = (int) buf;
657 fprintf(fp, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
661 int write_statistics(int flag, char * buf, char * reply_buf, int trace_status)
663 static FILE * fp = NULL;
664 int pre_size, size, count;
665 char * p = reply_buf;
667 fp = fopen ("write.output", "w");
670 if (flag == OPS_FLAG_INC) {
671 p = strstr (p, "pre-size");
673 sscanf (p, "pre-size %x", &pre_size);
674 p += strlen("pre-size");
675 p = strstr (p, "size");
677 sscanf (p, "size %x", &size);
678 p = strstr (p, "count");
680 fprintf (fp, "%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
682 sscanf (p, "count %x", &count);
683 fprintf (fp, "%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
685 if (flag == OPS_FLAG_PRINT) {
686 int disk_index = (int) buf;
687 int timestamp = (int) reply_buf;
688 fprintf(fp, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
692 void ops_statistics (int ops_flag, int proc, int timestamp)
694 static FILE * fp = NULL;
700 } ops[NOPS]={{0, 0, 0, "NULL"},{0, 0, 0, "GETATTR"},{0, 0, 1, "SETATTR"},{0, 0, 0, "ROOT"},
701 {0, 0, 0, "LOOKUP"},{0, 0, 0, "READLINK"},{0, 0, 0, "READ"},{0, 0, 1, "WRCACHE"},
702 {0, 0, 1, "WRITE"}, {0, 0, 1, "CREATE"},{0, 0, 1, "REMOVE"},{0, 0, 1, "RENAME"},
703 {0, 0, 1, "LINK"}, {0, 0, 1, "SYMLINK"},{0, 0, 1, "MKDIR"},{0, 0, 1, "RMDIR"},
704 {0, 0, 0, "READDIR"},{0, 0, 0, "FSSTAT"},{0, 0, 0, "ACCESS"},{0, 0, 0, "COMMIT"},
705 {0, 0, 0, "FSINFO"},{0, 0, 1, "MKNOD"}, {0, 0, 0, "PATHCONF"}, {0, 0, 0, "READDIRPLUS"}};
707 if (ops_flag == OPS_FLAG_INC) {
708 RFS_ASSERT (proc>=0 && proc<NOPS);
710 if (ops[proc].count == 1000) {
711 ops[proc].count_K ++;
715 if (ops_flag == OPS_FLAG_PRINT) {
717 int update_K=0, update=0, total_K=0, total=0;
719 int disk_index = proc;
722 fp = fopen ("mix.output", "w");
725 for (i=0; i<NOPS; i++) {
726 total_K += ops[i].count_K;
727 total += ops[i].count;
728 if (ops[i].update_flag) {
729 update_K += ops[i].count_K;
730 update += ops[i].count;
733 update_K += update/1000;
734 update = update%1000;
735 total_K += total/1000;
740 for (i=0; i<NOPS; i++) {
742 f2 = f2*1000+ops[i].count;
743 fprintf (fp, "%12s %8d,%03d %3.2f\%\n", ops[i].name, ops[i].count_K, ops[i].count, f2*100/f1);
744 fprintf (stderr, "%12s %8d,%03d %3.2f\%\n", ops[i].name, ops[i].count_K, ops[i].count, f2*100/f1);
748 fprintf (fp, " total %8d,%03d\n", total_K, total);
749 fprintf (stderr, " total %8d,%03d\n", total_K, total);
750 fprintf (fp, " update %8d,%03d %2.2f\%\n", update_K, update, f2*100/f1);
751 fprintf (stderr, " update %8d,%03d %2.2f\%\n", update_K, update, f2*100/f1);
752 fprintf(fp, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
753 fprintf(stderr, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
758 void truncate_statistics (int flag, int proc, char * buf, char * reply_buf)
760 #define TRACE_FH_SIZE2 16
761 #define BLOCK_SIZE 4096
762 static int no_size_num = 0;
763 static int have_size_num = 0;
764 static int equal_size_num = 0;
765 static int first_size_num = 0;
766 static int truncate_num = 0;
767 static int truncate_size = 0;
768 static int truncate_KB = 0;
769 static int truncate_block_num = 0;
770 static int padding_num = 0;
771 static int padding_KB = 0;
772 static int padding_size = 0;
773 static FILE * fp = NULL;
776 int pre_size, size, count;
777 struct generic_entry * ent;
779 if (flag == OPS_FLAG_PRINT) {
780 int disk_index = proc;
781 int timestamp = (int)buf;
783 fp = fopen ("truncate.output", "w");
786 truncate_KB += truncate_size/1000;
787 truncate_size %= 1000;
788 padding_KB += padding_size/1000;
789 padding_size %= 1000;
790 fprintf(fp, "###### disk_index %d timestamp %d no_size_req %d have_size_req %d equal_size_req %d trunc_req %d trunc_KB %d trunc_block_num %d padding_num %d padding_KB %d\n", disk_index, timestamp, no_size_num, have_size_num, equal_size_num, truncate_num, truncate_KB, truncate_block_num, padding_num, padding_KB);
791 fprintf(stderr, "###### disk_index %d timestamp %d no_size_req %d have_size_req %d equal_size_req %d trunc_req %d trunc_KB %d trunc_block_num %d padding_num %d padding_KB %d\n", disk_index, timestamp, no_size_num, have_size_num, equal_size_num, truncate_num, truncate_KB, truncate_block_num, padding_num, padding_KB);
795 p = strstr (&buf[TRACE_MSGID_POS], "fh");
801 p = strstr (buf, " size ");
803 RFS_ASSERT (proc==WRITE);
804 p = strstr (reply_buf, " ftype 1 ");
806 p = strstr (p, " size ");
808 if (strstr(p, " ftype 1 ")) {
809 fprintf (fp, "#### %s%s\n", buf, reply_buf);
810 fprintf (stderr, "#### %s%s\n", buf, reply_buf);
812 RFS_ASSERT (!strstr(p, " ftype 1 "));
820 sscanf (p, " size %x", &size);
821 if (size <0 || size > 2000000000) {
822 fprintf (fp, "#### size too big %x %s %s\n", size, buf, reply_buf);
823 fprintf (stderr, "#### size too big %x %s %s\n", size, buf, reply_buf);
826 RFS_ASSERT (size >=0 && size <2000000000);
827 ent = generic_lookup (trace_fh+24, TRACE_FH_SIZE2, 0, fh_htable, FH_HTABLE_SIZE);
829 if (ent->key3 != size) {
831 //printf ("%s\n", buf);
832 //printf ("size change fh %s pre-size %x size %x\n", trace_fh, ent->key3, size);
833 if (ent->key3 > size) {
835 truncate_size += ent->key3 - size;
836 truncate_block_num += (ent->key3+BLOCK_SIZE-1)/BLOCK_SIZE;
838 //fprintf (stderr, "truncate: pre_size %x size %x %s\n", ent->key3, size, buf);
839 //fprintf (fp, "truncate: pre_size %x size %x %s\n", ent->key3, size, buf);
840 truncate_block_num -= (size + BLOCK_SIZE-1)/BLOCK_SIZE;
842 if (truncate_size > 1000000000) {
843 truncate_KB += truncate_size/1000;
844 truncate_size %= 1000;
848 //printf ("%s\n", buf);
849 //printf ("padding fh %s pre-size %x size %x\n", trace_fh, ent->key3, size);
850 padding_size += size - ent->key3;
851 if (padding_size > 1000000000) {
852 padding_KB += padding_size/1000;
853 padding_size %= 1000;
861 generic_insert(trace_fh+24, TRACE_FH_SIZE2, size, fh_htable, FH_HTABLE_SIZE);
866 int get_timestamp (char * buf)
870 strncpy(str, buf, 100);
871 RFS_ASSERT (str[10]=='.');
874 RFS_ASSERT (ret >1000000000 && ret <2000000000);
878 int check_aging (char * tracefile)
886 int nfs3proc, msgid, proc;
888 while ((buf=read_line(++disk_index))!=NULL) {
889 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
891 if (buf[TRACE_VERSION_POS]!='3')
893 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
895 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
897 proc = nfs3proc_to_rfsproc[nfs3proc];
898 ops_statistics (OPS_FLAG_INC, proc, -1);
901 int off, count, size;
903 case CREATE: printf("%s\n", "create"); break;
904 case MKDIR: printf("%s\n", "mkdir"); break;
905 case REMOVE: printf("%s\n", "remove"); break;
906 case RMDIR: printf("%s\n", "rmdir"); break;
909 t = strstr (t, "off");
912 sscanf (t, "%x", &off);
913 RFS_ASSERT (off>=0 && off<0x7FFFFFFF)
914 t = strstr (t, "count");
917 sscanf (t, "%x", &count);
918 RFS_ASSERT (count <= 32768);
919 printf("%s off %x count %x\n", "write", off, count);
920 //printf("%s count %x\n", "write", count);
923 t = strstr (buf, " size ");
925 sscanf (t, " size %x", &size);
926 printf ("%s size %x\n", "setattr", size);
929 if ((disk_index%10000)==0) {
930 fprintf(stderr, "%d disk trace passed\n", disk_index);
934 fprintf(stderr, "%d disk trace parsed\n", disk_index);
935 ops_statistics (OPS_FLAG_PRINT, disk_index, -1);
939 int check_statistics (char * tracefile)
948 int nfs3proc, msgid, proc;
949 static int last_timestamp_sec = -1;
951 int memory_trace_size = 0;
953 while ((buf=read_line(++disk_index))!=NULL) {
954 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
956 if (buf[TRACE_VERSION_POS]!='3')
958 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
960 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
961 timestamp_sec = get_timestamp(buf);
963 proc = nfs3proc_to_rfsproc[nfs3proc];
964 ops_statistics (OPS_FLAG_INC, proc, -1);
966 if (proc!= WRITE && proc!=SETATTR && proc!=READ) {
969 RFS_ASSERT (buf[strlen(buf)-1]=='\n');
970 buf [strlen(buf)-1] = 0;
971 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
972 printf("disk_index %d strlen(buf) %d buf %s \n", disk_index, strlen(buf), buf);
973 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
975 printf("read line disk_index %d %s\n", disk_index, buf);
977 trace_status = NFS3ERR_RFS_MISS;
978 for (i=disk_index+1; i<disk_index+MAX_COMMAND_REPLY_DISTANCE; i++) {
979 reply_buf = read_line(i);
981 printf("searching for reply: read line %s\n", reply_buf);
984 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
985 p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
987 if (!strncmp(&reply_buf[TRACE_MSGID_POS], &buf[TRACE_MSGID_POS], p-&(reply_buf[TRACE_MSGID_POS]))) {
988 trace_status = find_reply_status(reply_buf);
989 if (trace_status == NFS3_OK) {
990 if (proc==READ || proc==WRITE)
991 read_write_fh_statistics (OPS_FLAG_INC, buf, 0);
993 write_statistics (OPS_FLAG_INC, buf, reply_buf, trace_status);
994 if (proc==WRITE || proc==SETATTR)
995 truncate_statistics (OPS_FLAG_INC, proc, buf, reply_buf);
1000 //if (memory_trace[memory_trace_size].trace_status == NFS3ERR_RFS_MISS)
1001 if (trace_status == NFS3ERR_RFS_MISS) {
1002 //printf ("%s no reply\n", buf);
1003 missing_reply_num ++;
1006 #if 0 /* commented out by G. Jason Peng */
1008 if ((missing_reply_num > memory_trace_size/10) && (missing_reply_num > 100)) {
1009 printf ("missing_reply_num %d too high for memory_trace_size %d\n", missing_reply_num, memory_trace_size);
1014 memory_trace_size ++;
1016 if (last_timestamp_sec == -1) {
1017 last_timestamp_sec = timestamp_sec;
1018 } else if (timestamp_sec - last_timestamp_sec >=3600) {
1019 ops_statistics (OPS_FLAG_PRINT, disk_index, timestamp_sec);
1020 truncate_statistics (OPS_FLAG_PRINT, disk_index, (char *)timestamp_sec, NULL);
1021 read_write_fh_statistics(OPS_FLAG_PRINT, (char *)disk_index, timestamp_sec);
1022 write_statistics(OPS_FLAG_PRINT, (char *)disk_index, (char *)timestamp_sec, -1);
1023 last_timestamp_sec = timestamp_sec;
1026 if ((memory_trace_size%10000)==0) {
1027 fprintf(stderr, "%d disk trace parsed, missing_reply %d\n", disk_index, missing_reply_num);
1028 ops_statistics (OPS_FLAG_PRINT, -1);
1029 truncate_statistics (OPS_FLAG_PRINT, -1, NULL, NULL);
1034 fprintf(stderr, "%d disk trace parsed, missing_reply %d\n", disk_index, missing_reply_num);
1035 ops_statistics (OPS_FLAG_PRINT, disk_index, timestamp_sec);
1036 truncate_statistics (OPS_FLAG_PRINT, disk_index, (char *)timestamp_sec, NULL);
1037 read_write_fh_statistics(OPS_FLAG_PRINT, (char *)disk_index, timestamp_sec);
1038 write_statistics(OPS_FLAG_PRINT, (char *)disk_index, (char *)timestamp_sec, -1);
1042 /* This routine output all the requests, together with their replies */
1043 int pair_trace (char * tracefile)
1052 int nfs3proc, msgid;
1053 int ops[NFS3_PROCEDURE_COUNT]={0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0};
1054 int memory_trace_size = 0;
1057 outputfp = fopen ("pair.output", "w");
1058 RFS_ASSERT (outputfp);
1060 while ((buf=read_line(++disk_index))!=NULL) {
1061 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1063 if (buf[TRACE_VERSION_POS]!='3')
1065 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1067 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1070 buf [strlen(buf)-1] = 0;
1071 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
1072 printf("disk_index %d strlen(buf) %d buf %s \n", disk_index, strlen(buf), buf);
1073 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
1075 printf("read line disk_index %d %s\n", disk_index, buf);
1076 fprintf (outputfp, "%s\n", buf);
1078 trace_status = NFS3ERR_RFS_MISS;
1079 for (i=disk_index+1; i<disk_index+MAX_COMMAND_REPLY_DISTANCE_FOR_PAIR; i++) {
1080 reply_buf = read_line(i);
1082 printf("searching for reply: read line %s\n", reply_buf);
1085 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1086 p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
1088 if (!strncmp(&reply_buf[TRACE_MSGID_POS], &buf[TRACE_MSGID_POS], p-&(reply_buf[TRACE_MSGID_POS]))) {
1089 fprintf(outputfp, "%s", reply_buf);
1090 trace_status = find_reply_status(reply_buf);
1092 fprintf(stderr, "reply found trace_status %d\n", find_reply_status(reply_buf));
1097 if (trace_status == NFS3ERR_RFS_MISS) {
1098 fprintf (stderr, "%s no reply\n", buf);
1099 fprintf(outputfp, "missing_reply\n");
1100 missing_reply_num ++;
1103 if (missing_reply_num > memory_trace_size/10 && missing_reply_num >100) {
1104 fprintf (stderr, "missing_reply_num %d too high for memory_trace_size %d\n", missing_reply_num, memory_trace_size);
1108 memory_trace_size ++;
1110 if ((memory_trace_size%10000)==0)
1111 fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, memory_trace_size, missing_reply_num );
1114 fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, memory_trace_size, missing_reply_num );
1115 //fprintf (stderr, "init_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);
1118 /* This routine output all the write requests, together with their replies. It is used for
1119 * analysis of write requests: appended bytes, overwrite bytes etc
1121 int pair_write (char * tracefile)
1129 int pair_write_debug = 0;
1130 int nfs3proc, msgid;
1131 int ops[NFS3_PROCEDURE_COUNT]={0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0};
1132 int memory_trace_size = 0;
1134 while ((buf=read_line(++disk_index))!=NULL) {
1135 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1137 if (buf[TRACE_VERSION_POS]!='3')
1139 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1141 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1144 if (!strstr(buf, "write"))
1147 buf [strlen(buf)-1] = 0;
1148 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
1149 printf("disk_index %d strlen(buf) %d buf %s \n", disk_index, strlen(buf), buf);
1150 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
1151 if (pair_write_debug)
1152 printf("read line disk_index %d %s\n", disk_index, buf);
1154 /* store the request to memory */
1155 //strcpy (memory_trace[memory_trace_size].line, buf);
1156 //memory_trace[memory_trace_size].disk_index = disk_index;
1158 /* find and store the reply status and reply fhandle to memory */
1159 //memory_trace[memory_trace_size].trace_status = NFS3ERR_RFS_MISS;
1160 trace_status = NFS3ERR_RFS_MISS;
1161 for (i=disk_index+1; i<disk_index+MAX_COMMAND_REPLY_DISTANCE_FOR_PAIR; i++) {
1162 reply_buf = read_line(i);
1163 if (pair_write_debug)
1164 printf("searching for reply: read line %s\n", reply_buf);
1167 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1168 p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
1170 if (!strncmp(&reply_buf[TRACE_MSGID_POS], &buf[TRACE_MSGID_POS], p-&(reply_buf[TRACE_MSGID_POS]))) {
1171 int pre_size, size, count;
1172 //memory_trace[memory_trace_size].trace_status = find_reply_status(reply_buf);
1173 if (pair_write_debug)
1174 printf("reply found trace_status %d\n", find_reply_status(reply_buf));
1176 trace_status = find_reply_status(reply_buf);
1177 if (trace_status == NFS3_OK) {
1178 p = strstr (p, "pre-size");
1180 sscanf (p, "pre-size %x", &pre_size);
1181 p += strlen("pre-size");
1182 p = strstr (p, "size");
1184 sscanf (p, "size %x", &size);
1185 p = strstr (p, "count");
1187 printf ("%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
1189 sscanf (p, "count %x", &count);
1190 printf ("%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
1196 //if (memory_trace[memory_trace_size].trace_status == NFS3ERR_RFS_MISS)
1197 if (trace_status == NFS3ERR_RFS_MISS) {
1198 printf ("%s no reply\n", buf);
1199 missing_reply_num ++;
1202 #if 0 /* commented out by G. Jason Peng */
1203 if (missing_reply_num > memory_trace_size/10) {
1204 printf ("missing_reply_num %d too high for memory_trace_size %d\n", missing_reply_num, memory_trace_size);
1209 memory_trace_size ++;
1212 if (memory_trace_size >= MAX_MEMORY_TRACE_LINES) {
1213 fprintf (stderr, "memory trace size %d is not enough\n", MAX_MEMORY_TRACE_LINES);
1217 if ((memory_trace_size%10000)==0)
1218 fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, memory_trace_size, missing_reply_num );
1221 fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, memory_trace_size, missing_reply_num );
1222 //fprintf (stderr, "init_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);
1233 memory_trace_ent_t * ent=NULL;
1235 start_profile (&read_trace_profile);
1237 while (!CYCLIC_FULL(memory_trace_index)) {
1238 if (ent!=NULL && (ent->trace_status == NFS3ERR_RFS_MISS))
1240 if ((buf=read_line(++disk_index))==NULL) {
1241 END: fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, CYCLIC_NUM(memory_trace_index), missing_reply_num );
1242 fprintf (stderr, "init_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);
1243 end_profile (&read_trace_profile);
1244 return TRACE_FILE_END;
1248 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1250 if (buf[TRACE_VERSION_POS]!='3')
1252 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
1253 printf("disk_index %d strlen(buf) %d buf %s \n", disk_index, strlen(buf), buf);
1254 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
1256 printf("read line disk_index %d %s\n", disk_index, buf);
1258 if (disk_index==1) {
1259 trace_timestamp1 = get_timestamp (buf);
1261 trace_timestamp2 = get_timestamp (buf);
1263 /* store the request to memory */
1264 ent = &(memory_trace[memory_trace_index.head]);
1265 strcpy (ent->line, buf);
1266 ent->disk_index = disk_index;
1268 if (MAX_COMMAND_REPLY_DISTANCE ==1) {
1269 ent->trace_status == NFS3ERR_RFS_MISS;
1271 reply_buf=read_line(++disk_index);
1272 RFS_ASSERT (reply_buf);
1273 if (!strcmp(reply_buf, "missing_reply\n")) {
1274 ent->trace_status == NFS3ERR_RFS_MISS;
1276 ent->trace_status = find_reply_status(reply_buf);
1280 if (ent->trace_status == NFS3ERR_RFS_MISS)
1281 missing_reply_num ++;
1283 if (MAX_COMMAND_REPLY_DISTANCE > 1) {
1284 if ((missing_reply_num > disk_index/5) && (missing_reply_num > 100)) {
1285 printf ("missing_reply_num %d too high for disk_index %d\n", missing_reply_num, disk_index);
1290 /* find and store the reply trace fhandle for create-class requests */
1291 if (ent->trace_status==NFS3_OK) {
1292 if (strstr(buf, "create") || strstr(buf, "mkdir")
1293 || (strstr(buf, "symlink") && (buf[TRACE_VERSION_POS]!='2'))
1294 || strstr(buf, "mknod") ) {
1295 p = find_reply_trace_fh(reply_buf);
1296 memcpy(ent->reply_trace_fh, p, TRACE_FH_SIZE);
1298 memset(ent->reply_trace_fh, 0, TRACE_FH_SIZE);
1301 add_to_dep_tab(memory_trace_index.head);
1303 if (((disk_index+1)%20000)==0) {
1304 fprintf(stderr, "%d disk trace parsed \n", disk_index+1);
1308 end_profile (&read_trace_profile);
1309 return TRACE_BUF_FULL;
1311 #else /* not defined REDUCE_MEMORY_TRACE_SIZE */
1319 fp = fopen(trace_file, "r");
1320 RFS_ASSERT (fp!=NULL);
1321 while (fgets(buf, MAX_TRACE_LINE_LENGTH, fp)) {
1322 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
1323 printf("strlen(buf) %d buf %s \n", strlen(buf), buf);
1324 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
1326 /* store the request to memory */
1327 strcpy (memory_trace[memory_trace_size].line, buf);
1328 memory_trace[memory_trace_size].disk_index = disk_index;
1329 memory_trace_size ++;
1331 if (memory_trace_size >= MAX_MEMORY_TRACE_LINES) {
1332 fprintf (stderr, "memory trace size %d is not enough\n", MAX_MEMORY_TRACE_LINES);
1335 if ((disk_index%100000)==0)
1336 fprintf(stderr, "%d disk trace parsed, store %d trace lines to memory\n", disk_index, memory_trace_size);
1340 fprintf(stderr, "total %d disk lines %d memory lines \n", disk_index, memory_trace_size );
1345 #ifdef REDUCE_MEMORY_TRACE_SIZE
1346 inline int disk_index_to_memory_index (int disk_index)
1348 static int memory_index = 0;
1350 RFS_ASSERT (!CYCLIC_EMPTY(memory_trace_index));
1351 RFS_ASSERT (memory_trace[memory_trace_index.tail].disk_index <= disk_index);
1352 RFS_ASSERT (memory_trace[CYCLIC_MINUS(memory_trace_index.head,1,memory_trace_index.size)].disk_index >=disk_index);
1353 if (disk_index > memory_trace[memory_index].disk_index) {
1354 while (memory_trace[memory_index].disk_index < disk_index) {
1355 memory_index = CYCLIC_ADD(memory_index,1,memory_trace_index.size);
1358 if (disk_index < memory_trace[memory_index].disk_index) {
1359 while (memory_trace[memory_index].disk_index > disk_index) {
1360 memory_index = CYCLIC_MINUS(memory_index,1,memory_trace_index.size);
1364 RFS_ASSERT (disk_index == memory_trace[memory_index].disk_index);
1365 return memory_index;
1368 #define disk_index_to_memory_index(disk_index) disk_index
1371 #define get_line_by_disk_index(disk_index) \
1372 memory_trace[disk_index_to_memory_index(disk_index)].line
1374 inline char * find_reply_line (char * command_line, int cur_disk_index)
1379 int request_memory_index = disk_index_to_memory_index (cur_disk_index);
1380 for (i=request_memory_index+1; i<request_memory_index+MAX_COMMAND_REPLY_DISTANCE && i<MAX_MEMORY_TRACE_LINES; i++) {
1381 line = memory_trace[i].line;
1382 if (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1383 p = strchr (&line[TRACE_MSGID_POS], ' ');
1385 if (!strncmp(&line[TRACE_MSGID_POS], &command_line[TRACE_MSGID_POS], p-&(line[TRACE_MSGID_POS])))
1392 inline int find_reply_status (char * line)
1397 //printf ("line %s flag %c\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
1398 RFS_ASSERT (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R');
1399 p = line+TRACE_MSGID_POS+2; /* at least one letter for msgid and one letter for space */
1400 if (strstr(p, "OK"))
1402 if (strstr(p, "lookup 2"))
1404 if (strstr(p, "create d"))
1406 if (strstr(p, "setattr 1"))
1408 if (strstr(p, "setattr 2712")) /* 10002 NFS3ERR_NOT_SYNC */
1410 if (strstr(p, "lookup d"))
1412 if (strstr(p, "read d"))
1414 if (strstr(p, "write d"))
1416 if (strstr(p, "write 46"))
1418 if (strstr(p, "getattr 46"))
1420 if (strstr(p, "mkdir d"))
1422 printf ("line %s flag %c return value weird\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
1423 printf ("!!!!!!!!!!!!!!!!!!!!!!!!\n");
1424 fprintf (stderr, "line %s flag %c return value weird\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
1425 fprintf (stderr, "!!!!!!!!!!!!!!!!!!!!!!!!\n");
1428 inline int find_reply_status_old (char * line)
1433 //printf ("line %s flag %c\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
1434 RFS_ASSERT (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R');
1435 if (!strstr(line, "OK")) {
1436 p=strstr(line, " 6 read ");
1438 p+=strlen(" 6 read ");
1440 p = strstr (line, "status=XXX");
1443 RFS_ASSERT (*p==' ');
1451 sscanf (p, "%x", &i);
1452 if ((i<=0) || (i>10000))
1453 printf("line %s\n", line);
1454 RFS_ASSERT (i>0 && i<10009);
1459 inline char * find_reply_trace_fh (char * line)
1462 p = strstr (line, "OK fh");
1464 printf ("find_reply_trace_fh line %s\n", line);
1469 #ifndef NO_DEPENDENCY_TABLE
1470 inline int disk_index_to_dep_index(int cur_dep_index, int disk_index)
1473 for (i=cur_dep_index; i>min_dep_index; i--) {
1474 if (dep_tab[i].disk_index == disk_index)
1481 inline int is_play_candidate (int dep_index)
1483 int proc = dep_tab[dep_index].proc;
1484 int status = dep_tab[dep_index].status;
1485 int trace_status = dep_tab[dep_index].trace_status;
1487 #ifndef TAKE_CARE_CREATE_MODE_BY_DAN
1488 /* for a failed create in trace, trace_replay just ignore many time the trace create fail
1489 * due to access control, but trace_play will success because our access control
1490 * may be loose (all uid/gid is mapped to single one 513:513, so we just skip these requests
1492 if ((proc==CREATE || proc==MKDIR) && (trace_status!=NFS3_OK) && (status!=NFS3ERR_RFS_MISS)) {
1493 if (dependency_debug)
1494 printf ("disk[%d] ignore failed create/mkdir in trace, trace_status %d line %s",
1495 dep_tab[dep_index].disk_index, trace_status, dep_tab[dep_index].line);
1496 failed_create_command_num ++;
1500 #ifndef TAKE_CARE_OTHER_FAILED_COMMAND
1501 if (((trace_status == NFS3ERR_ACCES) && (proc==READ || proc==WRITE || proc==LOOKUP)) ||
1502 ((trace_status == NFS3ERR_PERM) && (proc==SETATTR)) ){
1503 if (dependency_debug)
1504 printf ("disk[%d] ignore other failed command in trace, trace_status %d line %s",
1505 dep_tab[dep_index].disk_index, trace_status, dep_tab[dep_index].line);
1507 failed_other_command_num ++;
1511 #ifndef TAKE_CARE_SYMBOLIC_LINK
1512 if ((dep_tab[dep_index].proc==READLINK) ) { /* send request */
1513 skipped_readlink_command_num ++;
1517 /* This is actually take care in get_nextop by checking fh_map error when dep_index==min_dep_index */
1518 #ifndef TAKE_CARE_CUSTOM_COMMAND
1519 /* this line has a file handle which should belong to discard but it is not
1520 * the file handle directly appears as parent directory in a lookup request
1521 * the return value is NOENT, the parent directory should have been initialized
1522 * but the initialization code just ignored all lookup request which didn't success
1523 * including NOENT even though the parent directory is still valid.
1526 if (( ((dep_tab[dep_index].disk_index==262213) || (dep_tab[dep_index].disk_index==214402))
1527 && !(strcmp(trace_file, "anon-lair62-011130-1100.txt"))
1529 ( ((dep_tab[dep_index].disk_index==238460) || (dep_tab[dep_index].disk_index ==238470))
1530 && !(strcmp(trace_file, "anon-lair62-011130-1000.txt"))
1532 skipped_custom_command_num++;
1536 if (( ((dep_tab[dep_index].disk_index==423727) || (0))
1537 && !(strncmp(trace_file, "anon-lair62-011130-1500.txt", strlen("anon-lair62-011130-1500.txt")))
1539 ( ((dep_tab[dep_index].disk_index==238460) || (dep_tab[dep_index].disk_index ==238470))
1540 && !(strcmp(trace_file, "anon-lair62-011130-1000.txt"))
1542 skipped_custom_command_num++;
1545 /* this line is about the mkdir 116d9d originally in anon-lair62-011130-1400.txt */
1546 if (!strncmp(dep_tab[dep_index].line, "1007147245.194201", strlen("1007147245.194201"))) {
1547 skipped_custom_command_num++;
1551 #ifndef TAKE_CARE_FSSTAT_COMMAND
1552 /* the file handle used in this command is not processed properly by pre-processing */
1554 char * trace_fh = find_lead_trace_fh(proc, dep_tab[dep_index].line);
1555 fh_map_t * fh = lookup_fh (trace_fh);
1557 skipped_fsstat_command_num++;
1565 inline int is_dir_op (int proc)
1582 inline int is_create_op (int proc)
1584 if (proc==CREATE || proc==MKDIR || proc==LINK || proc==SYMLINK || proc==MKNOD || proc==RENAME)
1589 inline int is_delete_op (int proc)
1591 if (proc==REMOVE || proc==RMDIR || proc==RENAME)
1596 static inline char * find_lead_trace_fh(int proc, char * line)
1599 /* check the file handle availability */
1600 p = strstr (line, "fh");
1602 p+=3; //printf ("check dependency dep_tab[%d] trace_fh %s line %s \n", dep_index, trace_fh, line);
1606 inline char * find_another_trace_fh(int proc, char * line)
1609 /* check the file handle availability */
1610 p = strstr (line, "fh2");
1612 p+=4; //printf ("check dependency dep_tab[%d] trace_fh %s line %s \n", dep_index, trace_fh, line);
1616 /* return the index of next request in dep_tab.
1617 * Return -1 if there is no suitable request to send
1619 inline int get_nextop(void)
1623 static int dep_index = -2;
1626 #define INIT_MIN_WAIT_VALUE -999
1627 static int min_wait_fhandle_dep_index = INIT_MIN_WAIT_VALUE;
1631 if (min_wait_fhandle_dep_index == -999)
1632 min_wait_fhandle_dep_index = dep_window_index.head;
1634 for (i=0; i<CYCLIC_NUM(dep_window_index); i++) {
1635 dep_index = (dep_window_index.tail+i) % dep_window_index.size;
1637 proc = dep_tab[dep_index].proc;
1638 flag = dep_tab[dep_index].flag;
1640 if (dependency_debug)
1641 printf ("get_nextop check dep_tab[%d].disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
1642 #ifdef NO_DEPENDENCY_TABLE
1643 if (dep_tab[dep_index].flag == DEP_FLAG_INIT) {
1644 if (is_play_candidate(dep_index)==TRUE) {
1645 /* the trace_fh is the file handle for the operation directory, trace_fh_2 is other file handle
1646 * used in the request */
1647 if (proc==LINK || proc==RENAME) {
1648 dep_tab[dep_index].trace_fh = find_another_trace_fh (proc, dep_tab[dep_index].line);
1649 dep_tab[dep_index].trace_fh_2 = find_lead_trace_fh(proc, dep_tab[dep_index].line);
1650 dep_tab[dep_index].fh = 0;
1651 dep_tab[dep_index].fh_2 = 0;
1653 dep_tab[dep_index].trace_fh = find_lead_trace_fh(proc, dep_tab[dep_index].line);
1654 dep_tab[dep_index].fh = 0;
1655 dep_tab[dep_index].fh_2 = (fh_map_t *)1;
1657 dep_tab[dep_index].flag = DEP_FLAG_CANDIDATE;
1659 dep_tab[dep_index].skip_sec = skip_sec;
1661 if (dependency_debug)
1662 printf ("disk[%d] state DEP_FLAG_INIT to DEP_FLAG_CANDIDATE\n", dep_tab[dep_index].disk_index);
1664 if (dependency_debug)
1665 printf ("disk[%d] state DEP_FLAG_INIT to DEP_FLAG_DONE\n", dep_tab[dep_index].disk_index);
1666 dep_tab[dep_index].flag = DEP_FLAG_DONE;
1671 if ((dep_tab[dep_index].flag == DEP_FLAG_CANDIDATE) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_FHANDLE) ) {
1673 if (!dep_tab[dep_index].fh)
1674 dep_tab[dep_index].fh = lookup_fh (dep_tab[dep_index].trace_fh);
1675 if (!dep_tab[dep_index].fh_2)
1676 dep_tab[dep_index].fh_2 = lookup_fh (dep_tab[dep_index].trace_fh_2);
1678 /* need to wait for file handle */
1679 if ((!dep_tab[dep_index].fh) || (!dep_tab[dep_index].fh_2)) {
1680 if (dependency_debug)
1681 printf("disk[%d] can not lookup file handle\n", dep_tab[dep_index].disk_index);
1682 if (dep_tab[dep_index].flag == DEP_FLAG_CANDIDATE) {
1683 if (dependency_debug)
1684 printf ("disk[%d] state DEP_FLAG_CANDIDATE to DEP_FLAG_WAIT_FHANDLE\n", dep_tab[dep_index].disk_index);
1685 dep_tab[dep_index].flag = DEP_FLAG_WAIT_FHANDLE;
1686 sfs_gettime (&dep_tab[dep_index].start);
1687 if (CYCLIC_LESS(dep_tab_index,dep_index,min_wait_fhandle_dep_index))
1688 min_wait_fhandle_dep_index = dep_index;
1691 if (dep_index==dep_window_index.tail) {
1693 printf ("fh_path_map error disk[%d] state DEP_FLAG_WAIT_FHANDLE to DEP_FLAG_DONE\n", dep_tab[dep_index].disk_index);
1694 fh_path_map_err_num ++;
1695 dep_tab[dep_index].flag = DEP_FLAG_DONE;
1699 SUBTIME (tmp, dep_tab[dep_index].start);
1700 #define DEPENDENCY_TIMEOUT 5
1702 RFS_ASSERT (tmp.sec < DEPENDENCY_TIMEOUT + (skip_sec - dep_tab[dep_index].skip_sec));
1704 if (tmp.sec >= DEPENDENCY_TIMEOUT) {
1705 printf("dep_tab[%d].flag %d disk_index %d line %s\n", dep_index,
1706 dep_tab[dep_index].flag, dep_tab[dep_index].disk_index,
1707 dep_tab[dep_index].line);
1709 RFS_ASSERT (tmp.sec < DEPENDENCY_TIMEOUT );
1715 /* file handle ready, adjust_min_wait_fhandle_dep_index */
1716 if ((dep_tab[dep_index].flag == DEP_FLAG_WAIT_FHANDLE)) {
1717 if (dep_index == min_wait_fhandle_dep_index) {
1718 min_wait_fhandle_dep_index = dep_window_index.head;
1719 for (j=CYCLIC_ADD(dep_index,1,dep_window_index.size); CYCLIC_LESS(dep_window_index,j,dep_window_index.head); j++) {
1720 if (dep_tab[j].flag ==DEP_FLAG_WAIT_FHANDLE) {
1721 min_wait_fhandle_dep_index = j;
1727 if (dependency_debug)
1728 printf("disk[%d] found file handle\n", dep_tab[dep_index].disk_index);
1729 dep_tab[dep_index].flag = DEP_FLAG_FHANDLE_READY;
1731 /* the normal file operation can be executed now */
1732 if (!is_dir_op (dep_tab[dep_index].proc)) {
1733 if (dependency_debug)
1734 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
1738 if (dependency_debug)
1739 printf("disk[%d] directory operation \n", dep_tab[dep_index].disk_index);
1740 /* the directory operation need to lock the directory first */
1741 if (dep_tab[dep_index].fh->lock) {
1742 if (dependency_debug)
1743 printf ("disk[%d] state %d to DEP_FLAG_WAIT_DIRECTORY\n", dep_tab[dep_index].disk_index, dep_tab[dep_index].flag);
1744 dep_tab[dep_index].flag = DEP_FLAG_WAIT_DIRECTORY;
1749 if ((dep_tab[dep_index].flag == DEP_FLAG_FHANDLE_READY) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_DIRECTORY)) {
1750 int j = dep_tab[dep_index].fh - fh_map;
1751 if (dependency_debug) {
1752 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);
1753 printf ("trace_fh %s path %s\n", dep_tab[dep_index].fh->trace_fh, dep_tab[dep_index].fh->path);
1754 printf ("trace_fh %s path %s\n", fh_map[j].trace_fh, fh_map[j].path);
1756 if ((dep_tab[dep_index].fh->lock) || ((proc==RENAME) && (dep_tab[dep_index].fh_2->lock)) ) {
1757 if (dependency_debug)
1758 printf ("continue to wait for directory lock\n");
1761 if (dependency_debug)
1762 printf ("dep_tab[%d] disk index %d LOCK fh_map[%d] \n", dep_index, dep_tab[dep_index].disk_index, j);
1763 dep_tab[dep_index].fh->lock = 1;
1765 dep_tab[dep_index].fh_2->lock = 1;
1767 /* the non-delete directory operation can proceed now */
1768 if (!is_delete_op (dep_tab[dep_index].proc)) {
1769 if (dependency_debug)
1770 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
1774 /* the delete operation can proceed if nobody ahead is waiting for fhandle */
1775 /* probably this condition is not strong enough */
1776 // if ((min_wait_fhandle_dep_index<dep_index) ) {
1777 if (dep_index!=dep_window_index.tail) {
1778 if (dependency_debug)
1779 printf ("disk[%d] state %d to DEP_FLAG_WAIT_DELETE\n", dep_tab[dep_index].disk_index, dep_tab[dep_index].flag);
1780 dep_tab[dep_index].flag = DEP_FLAG_WAIT_DELETE;
1783 dep_tab[dep_index].flag = DEP_FLAG_DIRECTORY_READY;
1786 if ((dep_tab[dep_index].flag == DEP_FLAG_DIRECTORY_READY) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_DELETE)) {
1787 // if (min_wait_fhandle_dep_index > dep_index) {
1788 if (dep_index==dep_window_index.tail) {
1789 if (dependency_debug)
1790 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
1794 #else /*NO_DEPENDENCY_TABLE undefined */
1795 /* this part of code will be invalid after CYCLIC buffer design */
1796 if (dep_tab[dep_index].flag == DEP_FLAG_INIT){
1797 for (j=0, t=&(dep_tab[dep_index].dep_ops[0]);
1798 (j<dep_tab[dep_index].init_dep_num) && (dep_tab[dep_index].cur_dep_num>0);
1801 if (dep_tab[disk_index_to_dep_index(dep_index, *t)].flag == DEP_FLAG_DONE) {
1802 /* The depended request has been finished */
1804 dep_tab[dep_index].cur_dep_num --;
1809 if (dep_tab[dep_index].cur_dep_num == 0) {
1816 if (dependency_debug)
1817 printf ("get_nexop return -1\n");
1821 int check_timeout(void)
1823 static int biod_index = 0;
1825 int dep_index; /* index into dep_tab */
1827 sfs_op_type *op_ptr; /* per operation info */
1828 struct ladtime timeout;
1830 sfs_gettime (¤t);
1832 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
1833 if (biod_reqp[biod_index].in_use==TRUE) {
1834 timeout = biod_reqp[biod_index].timeout;
1835 if ((current.sec>timeout.sec) ||
1836 ((current.sec==timeout.sec) && (current.usec>timeout.usec))) {
1838 dep_index = biod_reqp[biod_index].dep_tab_index;
1839 proc = dep_tab[dep_index].proc;
1840 op_ptr = &Ops[proc];
1841 op_ptr->results.timeout_calls++;
1842 Ops[TOTAL].results.timeout_calls++;
1844 finish_request (biod_index, dep_index, NFS3ERR_RFS_TIMEOUT);
1846 if (is_create_op(proc)) {
1847 dep_tab[dep_index].flag = DEP_FLAG_CANDIDATE;
1848 printf ("resend dep_tab[%d], disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
1850 //RFS_ASSERT (!is_create_op(proc));
1852 //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);
1858 /* Allocate a biod_req entry to send and receive request dep_tab[dep_index]
1859 * build the cross reference between dep_tab entry and biod_req entry
1861 struct biod_req * get_biod_req(int dep_index) /* index into dep_tab */
1863 static int biod_index = 0;
1865 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
1866 if (!biod_reqp[biod_index].in_use) {
1867 biod_reqp[biod_index].in_use = 1;
1868 biod_reqp[biod_index].dep_tab_index = dep_index;
1869 dep_tab[dep_index].biod_req_index = biod_index;
1871 return &(biod_reqp[biod_index]);
1877 /* Return index into biod_reqp
1878 * return -1 upon failure
1880 int lookup_biod_req (int xid)
1882 static int biod_index = 0;
1884 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
1885 /* give a NULL as timeout pointer may cause indefinitely block */
1886 if (biod_reqp[biod_index].xid == xid) {
1893 extern struct ladtime test_start;
1894 void init_time_offset(void)
1896 struct ladtime tmp1;
1897 struct ladtime tmp2;
1900 test_start.usec = 0;
1901 sfs_gettime (&tmp1); /* called at initial time: tmp1 = play_starttime */
1903 DIVTIME (tmp1, PLAY_SCALE) /* tmp1 = play_starttime / SCALE */
1906 MULTIME (tmp1, PLAY_SCALE) /* tmp1 = play_starttime * SCALE */
1909 tmp2 = trace_starttime; /* tmp2 = trace_starttime */
1910 SUBTIME (tmp2, tmp1); /* tmp2 = trace_starttime - play_starttime *|/ SCALE */
1911 time_offset = tmp2; /* time_offset = trace_starttime - play_starttime *|/ SCALE */
1914 /* initialize timestamp and proc field of dep_tab entry */
1915 void init_dep_tab_entry (int dep_index)
1922 //line = get_line_by_disk_index (dep_tab[dep_index].disk_index);
1923 line = dep_tab[dep_index].line;
1924 sscanf (line, "%d.%d", &(dep_tab[dep_index].timestamp.tv_sec), &(dep_tab[dep_index].timestamp.tv_usec));
1925 sscanf (&line[39], "%x %x", &msgid, &nfsproc);
1926 if (line[TRACE_VERSION_POS]=='2') {
1927 dep_tab[dep_index].proc = nfs2proc_to_rfsproc[nfsproc];
1928 RFS_ASSERT (nfsproc <18);
1930 /* This is for debug purpose */
1931 if (line[TRACE_VERSION_POS] !='3') {
1932 fprintf(stderr, "line[TRACE_VERSION_POS] %c line %s\n", line[TRACE_VERSION_POS], line);
1933 line = get_line_by_disk_index (dep_tab[dep_index].disk_index-1);
1935 line = get_line_by_disk_index (dep_tab[dep_index].disk_index-2);
1937 fprintf(stderr, "previousline %s\n", line);
1939 RFS_ASSERT (line[TRACE_VERSION_POS] =='3');
1940 if (nfsproc >= NFS3_PROCEDURE_COUNT) {
1941 fprintf(stderr, "proc %d line %s\n", nfsproc, line);
1944 RFS_ASSERT (nfsproc <NFS3_PROCEDURE_COUNT);
1945 dep_tab[dep_index].proc = nfs3proc_to_rfsproc[nfsproc];
1947 RFS_ASSERT (dep_tab[dep_index].proc >= 0 && dep_tab[dep_index].proc < NOPS);
1948 dep_tab[dep_index].flag = DEP_FLAG_INIT;
1949 #ifndef REDUCE_MEMORY_TRACE_SIZE
1950 dep_tab[dep_index].reply_line = find_reply_line (line, dep_tab[dep_index].disk_index);
1951 if (dep_tab[dep_index].reply_line == NULL) {
1952 //printf ("disk[%d] can not find the reply line, assume trace_status OK\n", dep_tab[dep_index].disk_index);
1953 dep_tab[dep_index].trace_status = NFS3ERR_RFS_MISS;
1954 missing_reply_num ++;
1956 dep_tab[dep_index].trace_status = find_reply_status (dep_tab[dep_index].reply_line);
1960 void adjust_play_window (int flag, int * poll_timeout)
1962 struct ladtime max_window_time;
1963 static struct ladtime max_poll_time = {0, 2000, 0};
1967 cyclic_index_t old_dep_window_index = dep_window_index;
1970 printf ("^^^^^^^^^^^^^^^ adjust_play_window, begin\n");
1971 CYCLIC_PRINT (dep_tab_index);
1972 printf ("dep_tab[%d].memory_index %d\n", dep_tab_index.tail, dep_tab[dep_tab_index.tail].memory_index);
1973 CYCLIC_PRINT (dep_window_index);
1974 CYCLIC_PRINT (memory_trace_index);
1975 printf (" adjust_play_window, begin\n");
1978 while ((!CYCLIC_EMPTY(dep_window_index)) && (dep_tab[dep_window_index.tail].flag == DEP_FLAG_DONE)) {
1980 //CYCLIC_PRINT (memory_trace_index);
1981 //printf("MOVE_TAIL_TO memory_index %d\n", dep_tab[dep_tab_index.tail].memory_index);
1982 RFS_ASSERT (!CYCLIC_EMPTY(memory_trace_index));
1983 RFS_ASSERT (CYCLIC_LESS (memory_trace_index, dep_tab[dep_tab_index.tail].memory_index, memory_trace_index.head));
1984 printf("%d is done\n", dep_window_index.tail);
1986 CYCLIC_MOVE_TAIL(dep_tab_index);
1987 CYCLIC_MOVE_TAIL(dep_window_index);
1990 CYCLIC_PRINT (dep_tab_index);
1991 CYCLIC_PRINT (dep_window_index);
1993 if (! (dep_tab_index.tail == dep_window_index.tail)) {
1994 CYCLIC_PRINT(dep_tab_index);
1995 CYCLIC_PRINT(dep_window_index);
1997 RFS_ASSERT ( dep_tab_index.tail == dep_window_index.tail);
2000 if (!CYCLIC_EMPTY(dep_tab_index)) {
2002 RFS_ASSERT (!CYCLIC_EMPTY(memory_trace_index));
2003 if (!(CYCLIC_LESS (memory_trace_index, dep_tab[dep_tab_index.tail].memory_index, memory_trace_index.head))) {
2004 CYCLIC_PRINT(memory_trace_index);
2005 CYCLIC_PRINT(dep_tab_index);
2006 printf("dep_tab[head-1].memory_index, %d [tail].memory_index %d\n",
2007 dep_tab[CYCLIC_MINUS(dep_tab_index.head,1,dep_tab_index.size)].memory_index,
2008 dep_tab[dep_tab_index.tail].memory_index);
2010 RFS_ASSERT (CYCLIC_LESS (memory_trace_index, dep_tab[dep_tab_index.tail].memory_index, memory_trace_index.head));
2012 CYCLIC_SET_TAIL_TO(&memory_trace_index, dep_tab[dep_tab_index.tail].memory_index);
2013 //printf ("set memory_trace_index to %d=%d, dep_tab_index.tail %d\n", memory_trace_index.tail, dep_tab[dep_tab_index.tail].memory_index, dep_tab_index.tail);
2015 // CYCLIC_MOVE_TAIL (memory_trace_index);
2019 while (CYCLIC_EMPTY(dep_tab_index)) {
2021 if (disk_io_status == TRACE_FILE_END)
2024 //printf ("************** ADJUST_PLAY_WINDOW sleep 1 s\n");
2025 //print_cyclic_buffers();
2031 /* max_trace_window_time = current *|/ SCALE + trace_starttime */
2032 sfs_gettime (¤t);
2036 MULTIME (current, PLAY_SCALE);
2039 DIVTIME (current, PLAY_SCALE);
2041 ADDTIME (current, trace_starttime);
2042 max_window_time = current;
2044 /* Right now it is not clear how to deal with the situation where MAX_PLAY_WINDOW is reached */
2045 if (CYCLIC_NUM(dep_window_index) == MAX_PLAY_WINDOW) {
2046 //printf ("can not catch up the speed, dep_tab_size %d dep_window_max %d reach min_dep_index %d+MAX_PLAY_WINDOW\n", dep_tab_size, dep_window_max, min_dep_index);
2048 can_not_catch_speed_num ++;
2050 //RFS_ASSERT (dep_window_max < min_dep_index+MAX_PLAY_WINDOW);
2052 ADDTIME (current, trace_starttime);
2053 max_window_time = current;
2054 while ((CYCLIC_NUM(dep_window_index) < MAX_PLAY_WINDOW) &&
2055 (CYCLIC_NUM(dep_window_index) < CYCLIC_NUM(dep_tab_index)) ) {
2056 CYCLIC_MOVE_HEAD(dep_window_index);
2062 else if (CYCLIC_NUM(dep_window_index)==CYCLIC_NUM(dep_tab_index)) {
2063 *poll_timeout = 1000000; /* poll_timeout set to 1 second for the last request */
2067 struct ladtime tmp1;
2068 tmp.sec = dep_tab[dep_window_index.head].timestamp.tv_sec;
2069 tmp.usec = dep_tab[dep_window_index.head].timestamp.tv_usec;
2070 if (adjust_play_window_debug>=2)
2071 printf ("dep_tab[dep_window_index.head %d].timestamp %d:%d, max_window_time %d:%d\n",
2072 dep_window_index.head, tmp.sec, tmp.usec, max_window_time.sec, max_window_time.usec);
2074 SUBTIME (tmp, max_window_time);
2076 DIVTIME (tmp, PLAY_SCALE);
2079 MULTIME (tmp, PLAY_SCALE);
2084 if (tmp.sec > max_poll_time.sec) {
2087 printf ("dep_tab[%d].timestamp %d:%d, max_window_time %d:%d\n",
2088 dep_window_max, dep_tab[dep_window_max].timestamp.tv_sec, dep_tab[dep_window_max].timestamp.tv_usec, max_window_time.sec, max_window_time.usec);
2089 printf ("skip %d seconds\n", tmp.sec-max_poll_time.sec);
2090 SUBTIME (tmp, max_poll_time);
2092 skip_sec += tmp.sec;
2093 SUBTIME (test_start, tmp);
2094 tmp = max_poll_time;
2098 //RFS_ASSERT ((tmp.sec < 1000));
2101 if ((tmp.sec ==0) && (tmp.usec==0)) {
2104 *poll_timeout = tmp.sec*1000000+tmp.usec;
2108 struct ladtime tmp1;
2109 tmp.sec = dep_tab[dep_window_max].timestamp.tv_sec;
2110 tmp.usec = dep_tab[dep_window_max].timestamp.tv_usec;
2111 tmp1.sec = dep_tab[dep_window_max-1].timestamp.tv_sec;
2112 tmp1.usec = dep_tab[dep_window_max-1].timestamp.tv_usec;
2113 SUBTIME (tmp, tmp1);
2114 RFS_ASSERT ((tmp.sec < 1000));
2115 RFS_ASSERT ((tmp.sec>0) || ((tmp.sec==0) && (tmp.usec>0)));
2116 *poll_timeout = tmp.sec*1000000+tmp.usec;
2119 *poll_timeout = 100000;
2123 printf ("adjust_play_window: flag %d min %d -> %d, max %d -> %d poll_timeout %d \n",
2124 flag, old_dep_window_index.tail, dep_window_index.tail, old_dep_window_index.head,
2125 dep_window_index.head, *poll_timeout);
2128 printf ("^^^^^^^^^^^^^^^ adjust_play_window, end\n");
2129 CYCLIC_PRINT (dep_tab_index);
2130 printf ("dep_tab[%d].memory_index %d\n", dep_tab_index.tail, dep_tab[dep_tab_index.tail].memory_index);
2131 CYCLIC_PRINT (dep_window_index);
2132 CYCLIC_PRINT (memory_trace_index);
2133 printf (" adjust_play_window, end\n\n");
2138 /* poll for usecs and receive, after receive one reply,
2139 * return index in biod_reqp of the corresponding request
2141 int poll_and_get_reply (int usecs)
2143 int biod_index = -1;
2146 struct timeval zero_time = {0, 0}; /* Immediately return */
2149 error = biod_poll_wait (NFS_client, usecs);
2152 if (errno == EINTR) {
2157 (void) fprintf(stderr, "biod_poll_wait error\n");
2159 (void) fflush(stderr);
2166 error = get_areply_udp (NFS_client, &xid, &zero_time);
2167 // RFS_ASSERT (error!= RPC_TIMEOUT); /* we have polled and know there is data */
2168 // RFS_ASSERT (error!= RPC_CANTRECV);
2169 RFS_ASSERT (error == RPC_SUCCESS);
2171 biod_index = lookup_biod_req (xid);
2172 sfs_gettime (&(biod_reqp[biod_index].stop));
2181 void print_result(void)
2187 unsigned long long tmp;
2190 if (DEBUG_CHILD_GENERAL) {
2191 (void) fprintf(stdout, "trace play result:\n");
2192 (void) fprintf(stdout, "\t percentage good_cnt bad_cnt timeout_cnt\telapsed time\t\t\taverage time\n");
2193 for (i=0; i<NOPS+1; i++) {
2194 if (Ops[i].results.good_calls==0) {
2198 tmp = Ops[i].results.time.sec*1000000 + Ops[i].results.time.usec;
2200 avg_usecs = tmp/Ops[i].results.good_calls;
2202 avg_msecs = (Ops[i].results.time.sec*1000 + Ops[i].results.time.usec/1000)/Ops[i].results.good_calls;
2203 avg_usecs = (Ops[i].results.time.usec%1000)/Ops[i].results.good_calls;
2206 (void) fprintf(stdout, "%11s\t%4.1f\t%4d\t%4d\t%4d\t\tsec %8d usec %8d \tusec %8d\n",
2208 (float)(100*Ops[i].results.good_calls)/(float)Ops[TOTAL].results.good_calls,
2209 Ops[i].results.good_calls, Ops[i].results.bad_calls, Ops[i].results.timeout_calls,
2210 Ops[i].results.time.sec, Ops[i].results.time.usec, avg_msecs*1000+avg_usecs);
2212 (void) fflush (stdout);
2215 #if 0 /* commented out by G. Jason Peng */
2216 RFS_ASSERT (read_data_owe_GB==0);
2217 printf("read_data_total %d GB and %d bytes, owe %d GB and %d bytes, %d percent, adjusted %d times \n",read_data_total_GB, read_data_total, read_data_owe_GB, read_data_owe, (read_data_owe)/(read_data_total/100), read_data_adjust_times);
2218 printf("write_data_total %d GB and %d bytes, owe %d GB and %d bytes, %d percent, adjusted %d times \n",write_data_total_GB, write_data_total, write_data_owe_GB, write_data_owe, (write_data_owe)/(write_data_total/100), write_data_adjust_times);
2219 printf("poll_timeout_0_num %d poll_timeout_pos_num %d\n", poll_timeout_0_num, poll_timeout_pos_num);
2220 printf("failed_create_command_num_in_original_trace %d\nfailed_other_command_num_in_original_trace %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_err_due_to_parallel_remove %d\nlookup_eaccess_enoent_mismatch %d\nread_io_err_num %d\nstale_fhandle_err_num %d abnormal_EEXIST_num %d abnormal_ENOENT_num %d proper_reply_num %d run_stage_proper_reply_num %d\n",
2221 failed_create_command_num,
2222 failed_other_command_num,
2223 skipped_readlink_command_num,
2224 skipped_custom_command_num,
2225 fh_path_map_err_num,
2226 skipped_fsstat_command_num,
2228 rename_rmdir_noent_reply_num,
2229 rmdir_not_empty_reply_num,
2230 loose_access_control_reply_num,
2231 lookup_err_due_to_rename_num,
2232 lookup_err_due_to_parallel_remove_num,
2233 lookup_eaccess_enoent_mismatch_num,
2235 stale_fhandle_err_num,
2236 abnormal_EEXIST_num,
2237 abnormal_ENOENT_num,
2238 proper_reply_num, run_stage_proper_reply_num);
2241 clnt_destroy(NFS_client);
2244 // print_dump(Client_num, Child_num);
2248 * allocate and initialize client handles
2256 * Set up the client handles. We get them all before trying one
2257 * out to insure that the client handle for LOOKUP class is allocated
2258 * before calling op_getattr().
2260 if (DEBUG_CHILD_GENERAL) {
2261 (void) fprintf(stderr, "%s: set up client handle\n", sfs_Myname);
2264 NFS_client = lad_clnt_create(Tcp? 1: 0, Server_hostent,
2265 (uint32_t) NFS_PROGRAM,
2266 (uint32_t) nfs_version,
2267 RPC_ANYSOCK, &Nfs_timers[0]);
2269 if (NFS_client == ((CLIENT *) NULL)) {
2274 * create credentials using the REAL uid
2276 NFS_client->cl_auth = authunix_create(lad_hostname, (int)Real_uid,
2277 (int)Cur_gid, 0, NULL);
2280 if (biod_init(dummy, dummy) == -1) {
2293 /* Ready to go - initialize operation counters */
2294 for (i = 0; i < NOPS + 1; i++) {
2296 Ops[i].results.good_calls = 0;
2297 Ops[i].results.bad_calls = 0;
2298 Ops[i].results.timeout_calls = 0; // RFS
2299 Ops[i].results.fast_calls = 0;
2300 Ops[i].results.time.sec = 0;
2301 Ops[i].results.time.usec = 0;
2302 Ops[i].results.msec2 = 0;
2305 /* initialize timers and period variables */
2306 sfs_gettime(&Starttime);
2307 Cur_time = Starttime;
2308 start_msec = (Starttime.sec * 1000) + (Starttime.usec / 1000);
2309 Previous_chkpnt_msec = start_msec;
2310 Calls_this_period = 0;
2311 Reqs_this_period = 0;
2312 Sleep_msec_this_period = 0;
2313 Calls_this_test = 0;
2315 Sleep_msec_this_test = 0;
2319 nfs3_strerror(int status)
2321 static char str[40];
2324 (void) strcpy(str, "no error");
2327 (void) strcpy(str, "Not owner");
2330 (void) strcpy(str, "No such file or directory");
2333 (void) strcpy(str, "I/O error");
2336 (void) strcpy(str, "No such device or address");
2339 (void) strcpy(str, "Permission denied");
2342 (void) strcpy(str, "File exists");
2345 (void) strcpy(str, "Cross-device link");
2348 (void) strcpy(str, "No such device");
2350 case NFS3ERR_NOTDIR:
2351 (void) strcpy(str, "Not a directory");
2354 (void) strcpy(str, "Is a directory");
2357 (void) strcpy(str, "Invalid argument");
2360 (void) strcpy(str, "File too large");
2363 (void) strcpy(str, "No space left on device");
2366 (void) strcpy(str, "Read-only file system");
2369 (void) strcpy(str, "Too many links");
2371 case NFS3ERR_NAMETOOLONG:
2372 (void) strcpy(str, "File name too long");
2374 case NFS3ERR_NOTEMPTY:
2375 (void) strcpy(str, "Directory not empty");
2378 (void) strcpy(str, "Disc quota exceeded");
2381 (void) strcpy(str, "Stale NFS file handle");
2383 case NFS3ERR_REMOTE:
2384 (void) strcpy(str, "Object is remote");
2386 case NFS3ERR_BADHANDLE:
2387 (void) strcpy(str, "Bad file handle");
2389 case NFS3ERR_NOT_SYNC:
2390 (void) strcpy(str, "Not sync write");
2392 case NFS3ERR_BAD_COOKIE:
2393 (void) strcpy(str, "Bad cookie");
2395 case NFS3ERR_NOTSUPP:
2396 (void) strcpy(str, "Operation not supported");
2398 case NFS3ERR_TOOSMALL:
2399 (void) strcpy(str, "Value too small");
2401 case NFS3ERR_SERVERFAULT:
2402 (void) strcpy(str, "Server fault");
2404 case NFS3ERR_BADTYPE:
2405 (void) strcpy(str, "Bad type");
2407 case NFS3ERR_JUKEBOX:
2408 (void) strcpy(str, "Jukebox");
2410 case NFS3ERR_RFS_TIMEOUT:
2411 (void) strcpy(str, "Timeout");
2414 (void) sprintf(str, "Unknown status %d", status);
2421 * Check the gettimeofday() resolution. If the resolution
2422 * is in chunks bigger than SFS_MIN_RES then the client
2423 * does not have a usable resolution for running the
2430 char tmp_hostname[HOSTNAME_LEN];
2432 time_res = get_resolution();
2433 getmyhostname(tmp_hostname, HOSTNAME_LEN);
2434 if( time_res > (double)SFS_MIN_RES )
2436 (void) fprintf(stderr,
2437 "\n%s: Clock resolution too poor to obtain valid results.\n",
2439 (void) fprintf(stderr,
2440 "%s: Clock resolution %f Micro seconds.\n", tmp_hostname,
2446 (void) fprintf(stderr,
2447 "\n%s: Good clock resolution [ %f ] Micro seconds.\n",
2448 tmp_hostname, time_res);
2453 * Lifted code from Iozone with permission from author. (Don Capps)
2454 * Returns the resolution of the gettimeofday() function
2458 get_resolution(void)
2460 double starttime, finishtime, besttime;
2464 finishtime=time_so_far1(); /* Warm up the instruction cache */
2465 starttime=time_so_far1(); /* Warm up the instruction cache */
2466 delay=j=0; /* Warm up the data cache */
2471 starttime=time_so_far1();
2472 for(j=0;j< delay;j++)
2474 finishtime=time_so_far1();
2475 if(starttime==finishtime)
2480 besttime=(finishtime-starttime);
2481 if((finishtime-starttime) < besttime)
2482 besttime=(finishtime-starttime);
2491 * Lifted code from Iozone with permission from author. (Don Capps)
2492 * Returns current result of gettimeofday() in microseconds.
2494 /************************************************************************/
2495 /* Time measurement routines. */
2496 /* Return time in microseconds */
2497 /************************************************************************/
2502 /* For Windows the time_of_day() is useless. It increments in 55 */
2503 /* milli second increments. By using the Win32api one can get */
2504 /* access to the high performance measurement interfaces. */
2505 /* With this one can get back into the 8 to 9 microsecond */
2508 LARGE_INTEGER freq,counter;
2512 QueryPerformanceFrequency(&freq);
2513 QueryPerformanceCounter(&counter);
2514 bigcounter=(double)counter.HighPart *(double)0xffffffff +
2515 (double)counter.LowPart;
2516 wintime = (double)(bigcounter/(double)freq.LowPart);
2517 return((double)wintime*1000000.0);
2519 #if defined (OSFV4) || defined(OSFV3) || defined(OSFV5)
2522 if (getclock(TIMEOFDAY, (struct timespec *) &gp) == -1)
2524 return (( (double) (gp.tv_sec)*1000000.0) +
2525 ( ((float)(gp.tv_nsec)) * 0.001 ));
2529 if (gettimeofday(&tp, (struct timezone *) NULL) == -1)
2530 perror("gettimeofday");
2531 return ((double) (tp.tv_sec)*1000000.0) +
2532 (((double) tp.tv_usec) );
2540 fprintf(stderr, "trace play usage");
2542 extern void init_file_system (void)
2547 void show_fhandle (nfs_fh3 * fhp)
2549 struct knfs_fh * kfhp = (struct knfs_fh *)fhp;
2556 RFS_ASSERT (kfhp->fh_version == 1);
2557 RFS_ASSERT (kfhp->fh_fsid_type == 0);
2558 RFS_ASSERT (kfhp->fh_auth_type == 0);
2560 dev = ntohs(kfhp->fh_dev_major);
2562 dev = dev + ntohs(kfhp->fh_dev_minor);
2564 /* kfhp->fh_dev_ino hold the inode number of export point of the mounted
2565 * file system. For example, if /tmp/t1 is exported, /tmp/t1/t2 is mounted,
2566 * then fh_dev_ino hold the inode number of t1, not t2
2569 switch (kfhp->fh_fileid_type) {
2571 printf("fh:type 0 root dev 0x%x dev_ino %d\n", dev, kfhp->fh_dev_ino);
2574 printf("fh:type 1 %d %x dev %x dev_ino %x\n",
2575 kfhp->fh_ino, kfhp->fh_generation, dev, kfhp->fh_dev_ino);
2578 printf("fh:type2 %d %x dirino %d dev 0x%x dev_ino %x\n",
2579 kfhp->fh_ino, kfhp->fh_generation, kfhp->fh_dirino, dev, kfhp->fh_dev_ino);
2586 nfs_fh3 zero_fhandle;
2589 memset (fh_map, 0, sizeof (fh_map));
2590 memset(fh_htable, 0, sizeof (fh_htable));
2591 memset (&zero_fhandle, 0, sizeof(nfs_fh3));
2592 printf ("SIZE of fh map %d KB\n", sizeof (fh_map)/1000);
2596 int add_fh (int map_flag, char * trace_fh, char * path, nfs_fh3 * play_fh)
2598 char * old_trace_fh;
2600 /* first lookup if the entry for fh is already in the table */
2601 struct generic_entry * p;
2603 p = generic_lookup (trace_fh, TRACE_FH_SIZE, 0, fh_htable, FH_HTABLE_SIZE);
2605 RFS_ASSERT (fh_map[p->key3].flag = FH_MAP_FLAG_PARTIAL);
2606 RFS_ASSERT (map_flag ==FH_MAP_FLAG_COMPLETE);
2607 fh_map[p->key3].flag = map_flag;
2608 //RFS_ASSERT (!memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE));
2609 if (memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE)) {
2611 printf ("fh_map[%d].trace_fh %s trace_fh %s", p->key3, fh_map[p->key3].trace_fh, trace_fh);
2612 for (i=0; i<fh_i; i++) {
2613 int * p1 = (int *)&(fh_map[i].play_fh);
2614 #ifdef COMPRESS_TRACE_FH
2615 int * p = (int *)fh_map[i].trace_fh;
2616 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",
2617 i, *p, *(p+1), *(p+2), *(p+3), *(p+4), *(p+5), *(p+6), *(p+7), fh_map[i].path,
2618 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
2620 printf("fh_map[%d].trace_fh %s path %s \nnew_filehandle %8x%8x%8x%8x%8x%8x%8x%8x\n",
2621 i, fh_map[i].trace_fh, fh_map[i].path,
2622 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
2627 RFS_ASSERT (!strcmp(fh_map[p->key3].path, path));
2628 /* It's possible that in fh-path-map, many trace_fh are corresponding to one path
2629 * some of it may be the result of lookup after symlink, which is not handled
2630 * properly as new created objects
2632 #ifdef TAKE_CARE_SYMBOLIC_LINK
2633 RFS_ASSERT (!memcmp(&fh_map[p->key3].play_fh, &zero_fhandle, sizeof(nfs_fh3)));
2635 memcpy (&fh_map[p->key3].play_fh, play_fh, sizeof (nfs_fh3));
2636 if ((fh_map_debug==1)) // || (stage ==TRACE_PLAY_STAGE))
2637 printf ("update the play_fh for trace_fh %s path %s \n", trace_fh, path);
2641 fh_map[fh_i].flag = map_flag;
2642 fh_map[fh_i].lock = 0;
2643 strncpy(fh_map[fh_i].trace_fh, trace_fh, TRACE_FH_SIZE);
2645 RFS_ASSERT (strlen(path) < MAX_PLAY_PATH_SIZE);
2646 strcpy (fh_map [fh_i].path, path);
2647 if (map_flag==FH_MAP_FLAG_COMPLETE)
2648 memcpy (&fh_map[fh_i].play_fh, play_fh, sizeof(nfs_fh3));
2650 memset (&fh_map[fh_i].play_fh, 0, sizeof(nfs_fh3));
2652 if ((fh_map_debug==1)) { // || (stage ==TRACE_PLAY_STAGE)) {
2653 printf ("insert trace_fh %s path %s play_fh:\n", trace_fh, path);
2654 if (map_flag == FH_MAP_FLAG_COMPLETE) {
2655 //show_fhandle(play_fh);
2661 if (map_flag == FH_MAP_FLAG_DISCARD)
2662 printf ("insert flag %d trace_fh %s path %s play_fh:\n", map_flag, trace_fh, path);
2665 generic_insert(trace_fh, TRACE_FH_SIZE, fh_i, fh_htable, FH_HTABLE_SIZE);
2668 RFS_ASSERT (fh_i < FH_MAP_SIZE);
2673 inline fh_map_t * lookup_fh (char * trace_fh )
2675 struct generic_entry * p;
2676 p = generic_lookup (trace_fh, TRACE_FH_SIZE, 0, fh_htable, FH_HTABLE_SIZE);
2677 if (fh_map_debug==1)
2678 printf ("lookup trace_fh %s\n", trace_fh);
2681 if (fh_map_debug==1) {
2682 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);
2683 //show_fhandle(&fh_map[p->key3].play_fh);
2685 RFS_ASSERT (!memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE));
2686 return (&(fh_map[p->key3]));
2688 //printf ("lookup_fh %s not found\n", trace_fh);
2689 if (stage != READ_DEP_TAB_STAGE && (fh_map_debug==1)) {
2690 printf ("lookup not found trace_fh %s\n", trace_fh);
2697 int delete_fh (char * trace_fh, int fh_map_index)
2699 generic_delete (trace_fh, TRACE_FH_SIZE, fh_map_index, fh_htable, FH_HTABLE_SIZE);
2703 int lookup_init_filesystem (nfs_fh3 * parent, char * name, nfs_fh3 * result)
2706 LOOKUP3res reply; /* the reply */
2707 enum clnt_stat rpc_stat; /* result from RPC call */
2708 struct ladtime start;
2709 struct ladtime stop;
2712 /* set up the arguments */
2713 (void) memcpy((char *) &args.what.dir, (char *) parent,
2715 args.what.name = name;
2716 (void) memset((char *) &reply.resok.object, '\0', sizeof (nfs_fh3));
2719 sfs_gettime(&start);
2720 rpc_stat = clnt_call(NFS_client, NFSPROC3_LOOKUP,
2721 xdr_LOOKUP3args, (char *) &args,
2722 xdr_LOOKUP3res, (char *) &reply,
2726 if (rpc_stat !=RPC_SUCCESS) {
2727 printf("rpc_stat %d\n", rpc_stat);
2730 RFS_ASSERT (rpc_stat == RPC_SUCCESS);
2731 (void) memcpy((char *) result, (char *) &reply.resok.object, sizeof (nfs_fh3));
2732 return (reply.status);
2735 void read_fh_map(char * fh_map_file)
2740 char trace_fh[TRACE_FH_SIZE];
2745 #define MAX_PATH_DEPTH 20
2746 nfs_fh3 parents[MAX_PATH_DEPTH];
2747 char * lookup_path_ptr[MAX_PATH_DEPTH];
2748 char lookup_path [MAX_PLAY_PATH_SIZE];
2750 int new_dir_flag = 0;
2754 memset(lookup_path_ptr, 0, sizeof(lookup_path_ptr));
2755 memcpy(&parents[depth], &(Export_dir.fh_data->sfs_fh_un.f_fh3), sizeof(nfs_fh3));
2756 strcpy(lookup_path, "/");
2757 lookup_path_ptr[depth]=&lookup_path[0];
2759 fp = fopen(fh_map_file, "r");
2761 printf ("can not opern %s\n", fh_map_file);
2765 RFS_ASSERT (fp!=NULL);
2769 memset(buf, 0, sizeof(buf));
2770 while (fgets(buf, 1024, fp)) {
2772 if (fh_i % 10000==0)
2773 printf("%d fh_map entry read\n", fh_i);
2775 RFS_ASSERT (buf[strlen(buf)-1]=='\n');
2776 buf[strlen(buf)-1]=0;
2778 printf("%d fgets return %s\n", fh_i, buf);
2779 printf("depth %d lookup_path %s\n", depth, lookup_path);
2781 //for (i=0; i<=depth; i++)
2782 //printf("lookup_path_ptr[%d] %s ", i, lookup_path_ptr[i]);
2784 #ifdef COMPRESS_TRACE_FH
2785 for (i=0; i<TRACE_FH_SIZE/8; i++) {
2786 strncpy(intbuf, buf+i*8, 8);
2787 sscanf(intbuf, "%x", trace_fh+i*8); // maybe it should be 4, anyway we don't compress for now
2789 trace_path = buf+TRACE_FH_SIZE*2+1; /* +1 the trace contains only initial file handle */
2791 memcpy(trace_fh, buf, TRACE_FH_SIZE);
2792 trace_path = buf + TRACE_FH_SIZE +1;
2794 #ifdef TRACE_CONTAIN_LATER_FHANDLE
2795 trace_path = +=2; /* +3 if the trace contains both initial and later created file handle */
2798 #ifdef NO_DEPENDENCY_TABLE
2799 if (!strncmp (trace_path, "DISCARD", 7) ||
2800 !strncmp (trace_path, "LN", 2) ) {
2801 map_flag = FH_MAP_FLAG_DISCARD;
2802 add_fh (map_flag, buf, trace_path, 0);
2807 p = trace_path+strlen(trace_path)-2;
2811 //RFS_ASSERT (p-trace_path<=strlen(lookup_path)+1);
2812 //RFS_ASSERT (p>trace_path);
2814 if (strncmp(lookup_path, trace_path, p-trace_path)) {
2815 printf("strncmp lookup_path %s trace_path %s for length %d\n", lookup_path, trace_path, p-trace_path);
2817 RFS_ASSERT (!strncmp(lookup_path, trace_path, p-trace_path));
2818 //while (strncmp(lookup_path, trace_path, p-trace_path)) { /* one step deeper */
2819 while (strlen(lookup_path)>p-trace_path && depth>0) {
2820 //printf("depth--\n");
2822 printf ("lookup_path %s trace_path %s p-trace_path %d depth %d\n", lookup_path, trace_path, p-trace_path, depth);
2823 RFS_ASSERT (depth>0);
2824 *lookup_path_ptr[depth]=0;
2825 lookup_path_ptr[depth]=0;
2828 RFS_ASSERT (strlen(lookup_path)==(p-trace_path) || (depth==0));
2831 #ifdef TRACE_CONTAIN_LATER_FHANDLE
2832 if (buf[TRACE_FH_SIZE*2+1]=='Y') {
2833 map_flag = FH_MAP_FLAG_COMPLETE;
2835 map_flag = FH_MAP_FLAG_PARTIAL;
2836 RFS_ASSERT (buf[TRACE_FH_SIZE*2+1]=='N');
2839 map_flag = FH_MAP_FLAG_COMPLETE;
2841 if ((*(p+strlen(p)-1))=='/') {
2847 if (map_flag == FH_MAP_FLAG_COMPLETE) {
2848 int ret = lookup_init_filesystem (&parents[depth], p, &parents[depth+1]);
2850 printf ("lineno %d %s\n", lineno, buf);
2852 RFS_ASSERT (ret == NFS3_OK);
2853 add_fh (map_flag, buf, trace_path, &parents[depth+1]);
2855 add_fh (map_flag, buf, trace_path, 0);
2858 /* the new fhandle is of a directory */
2859 lookup_path_ptr[depth+1] = lookup_path+strlen(lookup_path);
2860 strcat (lookup_path, p);
2861 strcat (lookup_path, "/");
2863 //printf("depth++\n");
2867 memset(buf, 0, sizeof(buf));
2871 for (i=0; i<fh_i; i++) {
2872 int * p1 = (int *)&(fh_map[i].play_fh);
2873 #ifdef COMPRESS_TRACE_FH
2874 int * p = (int *)fh_map[i].trace_fh;
2875 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",
2876 i, *p, *(p+1), *(p+2), *(p+3), *(p+4), *(p+5), *(p+6), *(p+7), fh_map[i].path,
2877 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
2879 printf("fh_map[%d].trace_fh %s path %s \nnew_filehandle %8x%8x%8x%8x%8x%8x%8x%8x\n",
2880 i, fh_map[i].trace_fh, fh_map[i].path,
2881 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
2885 fprintf(stderr, "total %d requests \n", i);
2894 inline free_biod_req (int biod_index)
2896 RFS_ASSERT (biod_reqp[biod_index].in_use == TRUE);
2897 biod_reqp[biod_index].in_use = FALSE;
2901 inline void finish_request (int biod_index, int dep_index, int status)
2903 /* the ending operation, same as when a request time out */
2905 dep_tab[dep_index].stop = biod_reqp[biod_index].stop; /* RFS: to dump data */
2906 free_biod_req (biod_index);
2908 dep_tab[dep_index].status = status;
2909 if (event_order_index < EVENT_ORDER_SIZE)
2910 event_order[event_order_index++] = -dep_tab[dep_index].disk_index;
2912 dep_tab[dep_index].flag = DEP_FLAG_DONE;
2913 if (is_dir_op(dep_tab[dep_index].proc)) {
2915 RFS_ASSERT (dep_tab[dep_index].fh->lock = 1);
2916 dep_tab[dep_index].fh->lock = 0;
2917 if (dep_tab[dep_index].proc==RENAME)
2918 dep_tab[dep_index].fh_2->lock = 0;
2919 j = dep_tab[dep_index].fh-fh_map;
2920 if (dependency_debug) {
2921 printf ("fh_map[%d] is UNlocked\n",j);
2922 printf ("trace_fh %d path %s\n", dep_tab[dep_index].fh->trace_fh, dep_tab[dep_index].fh->path);
2923 printf ("trace_fh %d path %s\n", fh_map[j].trace_fh, fh_map[j].path);
2928 /* the request argument may have pointers pointing to buffers, e.g. the name in lookup,
2929 * the target of symlink, the write data */
2930 char arg_res[MAX_ARG_RES_SIZE];
2931 int poll_timeout = 0; /* timeout in usecs */
2932 char buf1 [MAX_BUF1_SIZE];
2933 char buf2 [MAX_BUF2_SIZE];
2935 int execute_next_request ()
2940 struct biod_req * reqp;
2941 sfs_op_type *op_ptr; /* per operation info */
2942 struct ladtime call_timeout;
2943 static int last_print_time = -1;
2945 if (num_out_reqs == max_biod_reqs) {
2949 start_profile (&valid_get_nextop_profile);
2950 start_profile (&invalid_get_nextop_profile);
2951 dep_index = get_nextop();
2952 if (dep_index == -1) {
2953 end_profile (&invalid_get_nextop_profile);
2956 end_profile (&valid_get_nextop_profile);
2958 start_profile (&prepare_argument_profile);
2959 line = dep_tab[dep_index].line;
2961 end_profile(&total_profile);
2962 if ((total_profile.in.tv_sec - last_print_time >= 10)) {
2963 last_print_time = total_profile.in.tv_sec;
2964 //fprintf (stderr, "time %d processing dep_tab[%d] disk_index %d num_out_reqs %d can_not_catch_speed_num %d PLAY_SCALE %d \n", total_profile.in.tv_sec, dep_index, dep_tab[dep_index].disk_index, num_out_reqs, can_not_catch_speed_num, PLAY_SCALE);
2965 fprintf (stdout, "time %d processing dep_tab[%d] disk_index %d num_out_reqs %d can_not_catch_speed_num %d PLAY_SCALE %d \n", total_profile.in.tv_sec, dep_index, dep_tab[dep_index].disk_index, num_out_reqs, can_not_catch_speed_num, PLAY_SCALE);
2967 CYCLIC_PRINT (dep_tab_index);
2969 int tmp = CYCLIC_MINUS(dep_tab_index.head,1,dep_tab_index.size);
2970 printf("dep_tab_index.head-1 %d disk_index %d tail %d disk_index %d\n", tmp, dep_tab[tmp].disk_index,
2971 dep_tab_index.tail, dep_tab[dep_tab_index.tail].disk_index);
2977 if (can_not_catch_speed_num < 2000) {
2979 printf ("set PLAY_SCALE to %d\n", PLAY_SCALE);
2981 if (can_not_catch_speed_num > 50000) {
2984 if (can_not_catch_speed_num > 5000) {
2992 if ((total_profile.in.tv_sec > 100)) {
2993 can_not_catch_speed_num_total += can_not_catch_speed_num;
2995 can_not_catch_speed_num = 0;
2999 printf ("processing dep_tab[%d] disk_index %d %s\n", dep_index, dep_tab[dep_index].disk_index, line);
3001 proc = dep_tab[dep_index].proc;
3002 rfs_Ops[proc].setarg (dep_index, line, arg_res, buf1, buf2);
3004 op_ptr = &Ops[proc];
3005 reqp = get_biod_req (dep_index);
3008 #ifdef notdef /* place to set request timeout. G. Jason Peng */
3009 call_timeout.sec = 2; //Nfs_timers[op_ptr->call_class].tv_sec;
3010 call_timeout.usec = Nfs_timers[op_ptr->call_class].tv_usec;
3012 call_timeout.sec = 0;
3013 call_timeout.usec = 500000;
3014 //call_timeout.usec = 14000;
3015 //call_timeout.usec = 13000;
3016 //call_timeout.usec = 6000;
3017 //call_timeout.usec = 8000;
3018 //call_timeout.usec = 10000;
3022 sfs_gettime(&(reqp->start));
3023 end_profile (&prepare_argument_profile);
3024 start_profile (&biod_clnt_call_profile);
3027 reqp->xid = biod_clnt_call(NFS_client, rfs_Ops[proc].nfsv3_proc,
3028 rfs_Ops[proc].xdr_arg, arg_res);
3031 reqp->xid = dep_index+1; /* just fake a message id and let it expire */
3033 RFS_ASSERT (reqp->xid != 0);
3034 reqp->timeout = reqp->start;
3035 ADDTIME (reqp->timeout, call_timeout);
3036 dep_tab[dep_index].flag = DEP_FLAG_SENT;
3037 if (event_order_index < EVENT_ORDER_SIZE)
3038 event_order[event_order_index++] = dep_tab[dep_index].disk_index;
3040 dep_tab[dep_index].start = reqp->start; /* RFS: to dump data */
3041 end_profile (&biod_clnt_call_profile);
3044 void check_reply (int proc, int biod_index, int dep_index, int status, char * errmsg, int trace_status)
3046 if (((status!=trace_status)) && (status!=NFS3_OK) && (trace_status!=NFS3ERR_RFS_MISS)) {
3048 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);
3049 #ifndef TAKE_CARE_UNLOOKED_UP_NON_NEW_FILES
3050 /* these files is not looked up and is not create/mkdir/symlink/link/mknod ed before they
3051 * are refered by name through rename, remove
3053 if ((proc==RENAME || proc==REMOVE) && (status==NFS3ERR_NOENT) && (trace_status ==0)) {
3054 /* current initialization doesnot take care of rename source, if there is no
3055 * create or lookup before that source, the source object will not exist when
3058 rename_rmdir_noent_reply_num++;
3061 #ifndef TAKE_CARE_SYMBOLIC_LINK
3062 if ((proc==LOOKUP) && (status==NFS3_OK) && (trace_status==NFS3ERR_NOENT)) {
3063 /* in the original trace, first lookup return NOENT, then symlink is executed, then lookup return OK
3064 * the initialization considers only the lookup return OK and created the file in the initialization
3065 * so in trace play the first lookup return OK
3068 } else // if ((proc==SYMLINK) && (status == NFS3ERR_EXIST) && (trace_status == 0)) {
3069 /* trace_status could be EAGAIN */
3070 if ((proc==SYMLINK) && (status == NFS3ERR_EXIST) ) {
3071 /* due to similar reason as above, the initialization code initializes the symbolic link as a normal
3077 #ifndef TAKE_CARE_NOEMPTY_RMDIR
3078 /* the remove packet seems got lost in the trace capture, so replay can not finish */
3079 if ((proc==RMDIR) && (status==NFS3ERR_NOTEMPTY)) {
3081 RENAME3res reply; /* the reply */
3082 RMDIR3args * rmdir_argp;
3083 enum clnt_stat rpc_stat; /* result from RPC call */
3085 rfs_Ops[proc].setarg (dep_index, dep_tab[dep_index].line, arg_res, buf1, buf2);
3086 rmdir_argp = (RMDIR3args *)arg_res;
3088 memcpy(&args.from, &(rmdir_argp->object), sizeof (diropargs3));
3089 memcpy(&args.to.dir, &(Export_dir.fh_data->sfs_fh_un.f_fh3), sizeof(nfs_fh3));
3090 args.from.name = buf1; /* the buf1 is already filled when parsing rmdir */
3091 args.to.name = buf2;
3092 sprintf(buf2, "rmdir_%d_%s", dep_tab[dep_index].disk_index, rmdir_argp->object.name);
3094 rpc_stat = clnt_call(NFS_client, NFSPROC3_RENAME,
3095 xdr_RENAME3args, (char *) &args,
3096 xdr_RENAME3res, (char *) &reply,
3098 RFS_ASSERT (rpc_stat == RPC_SUCCESS);
3099 if (reply.status!=NFS3_OK)
3100 printf ("change rmdir into rename, reply.status %d\n", reply.status);
3101 RFS_ASSERT (reply.status==NFS3_OK);
3102 rmdir_not_empty_reply_num ++;
3104 #ifndef TAKE_CARE_ACCESS_ERROR
3105 } else if ((status==0) && (trace_status==NFS3ERR_ACCES)) {
3106 loose_access_control_reply_num ++;
3108 #ifdef NO_DEPENDENCY_TABLE
3109 } else if ((proc==LOOKUP) && (status==NFS3ERR_NOENT) && (trace_status==NFS3_OK)) {
3110 lookup_err_due_to_rename_num ++;
3111 } else if ((proc==LOOKUP) && (status==NFS3_OK) && (trace_status == NFS3ERR_NOENT)) {
3112 /* if there is a remove in front of the lookup, but it is
3113 * actually executed later than the lookup
3115 lookup_err_due_to_parallel_remove_num ++;
3117 #ifndef TAKE_CARE_LOOKUP_EACCESS_ENOENT_MISMATCH
3118 /* if the looked return EACCESS in the trace, means the object still exists
3119 * should have initialized, right not don't initialize it, hence play status
3122 } else if ((proc==LOOKUP) && (status==NFS3ERR_NOENT) && (trace_status==NFS3ERR_ACCES)) {
3123 lookup_eaccess_enoent_mismatch_num ++;
3125 #ifdef TOLERANT_READ_IO_ERR
3126 } else if ((proc==READ) && (status==NFS3ERR_IO) && (trace_status==NFS3_OK)) {
3129 #ifdef TOLERANT_STALE_FHANDLE_ERR
3130 } else if ((status==NFS3ERR_STALE) && (trace_status==NFS3_OK)) {
3131 printf ("!!!!!!! STALE FILE HANDLE \n");
3133 stale_fhandle_err_num ++;
3137 for (i=dep_window_index.tail; CYCLIC_LESS(dep_window_index,i,dep_window_index.head); i++)
3138 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);
3139 if (status==EEXIST) {
3140 abnormal_EEXIST_num ++;
3141 } else if (status == ENOENT) {
3142 abnormal_ENOENT_num ++;
3147 proper_reply_num ++;
3148 if (total_profile.in.tv_sec >= WARMUP_TIME)
3149 run_stage_proper_reply_num ++;
3154 /* return -1 if there is no reply being received
3155 * return the dep_index if the corresponding reply has been received
3157 inline int receive_next_reply (int busy_flag)
3164 sfs_op_type *op_ptr; /* per operation info */
3170 /* wait for reply */
3171 start_profile (&valid_poll_and_get_reply_profile);
3172 start_profile (&invalid_poll_and_get_reply_profile);
3174 if (busy_flag == BUSY) {
3176 poll_timeout_0_num ++;
3178 poll_timeout = 2000; /* 10000 or 2000 is a better number in non-debugging state */
3179 //poll_timeout = 0; /* 10000 or 2000 is a better number in non-debugging state */
3180 poll_timeout_pos_num ++;
3183 biod_index = poll_and_get_reply (poll_timeout);
3184 if (biod_index==-1) {
3185 end_profile (&invalid_poll_and_get_reply_profile);
3188 end_profile (&valid_poll_and_get_reply_profile);
3190 start_profile (&decode_reply_profile);
3191 /* check the corresponding request */
3192 dep_index = biod_reqp[biod_index].dep_tab_index;
3193 if (biod_reqp[biod_index].in_use==1) {
3194 RFS_ASSERT (dep_tab[dep_index].biod_req_index == biod_index);
3196 printf ("biod_index %d reply received but the request has been time out\n", biod_index);
3200 proc = dep_tab[dep_index].proc;
3201 op_ptr = &Ops[proc];
3203 if (dep_tab[dep_index].flag != DEP_FLAG_SENT) {
3204 printf("dep_tab[%d].flag %d proc %d status %d start %d:%d stop %d:%d\n",
3205 dep_index, dep_tab[dep_index].flag, proc, dep_tab[dep_index].status,
3206 dep_tab[dep_index].start.sec, dep_tab[dep_index].start.usec,
3207 dep_tab[dep_index].stop.sec, dep_tab[dep_index].stop.usec );
3208 printf ("received reply for timeout requests dep_tab[%d].disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
3211 RFS_ASSERT (dep_tab[dep_index].flag == DEP_FLAG_SENT);
3213 /* decode the reply */
3214 rfs_Ops[proc].setres (arg_res, buf1);
3215 ret = proc_header (NFS_client, rfs_Ops[proc].xdr_res, arg_res);
3216 RFS_ASSERT (ret == RPC_SUCCESS);
3217 status = *((int *)arg_res);
3218 errmsg = nfs3_strerror (status);
3219 end_profile (&decode_reply_profile);
3221 start_profile (&check_reply_profile);
3222 /* compare with the reply in the trace */
3223 line = dep_tab[dep_index].line;
3224 reply_line = dep_tab[dep_index].reply_line;
3225 trace_status = dep_tab[dep_index].trace_status;
3227 /* print the result, trace play progress indicator
3228 if (rfs_debug || ( !profile_debug && ((dep_index %10000)==0) ) )
3229 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);
3232 /* error checking */
3233 check_reply (proc, biod_index, dep_index, status, errmsg, trace_status);
3235 /* free resources */
3236 finish_request (biod_index, dep_index, status);
3238 /* we set 100 seconds warm up time */
3239 if ((total_profile.in.tv_sec >= WARMUP_TIME)) {
3240 /* get statistics */
3241 if (status == trace_status || (status==NFS3_OK && trace_status==NFS3ERR_RFS_MISS) ) {
3242 op_ptr->results.good_calls++;
3243 Ops[TOTAL].results.good_calls++;
3245 op_ptr->results.bad_calls++;
3246 Ops[TOTAL].results.bad_calls++;
3248 sfs_elapsedtime (op_ptr, &(biod_reqp[biod_index].start), &(biod_reqp[biod_index].stop));
3249 end_profile (&check_reply_profile);
3252 //start_profile (&add_create_object_profile);
3254 if (trace_status == NFS3_OK && (proc==CREATE || proc==MKDIR || proc==SYMLINK || proc==MKNOD)) {
3255 #ifndef REDUCE_MEMORY_TRACE_SIZE
3256 RFS_ASSERT (reply_line);
3258 if (status!=NFS3_OK) {
3259 /* commented out for 1022 */
3260 printf ("!!!!!! Should have been an ASSERTION FAILURE \n");
3261 RFS_ASSERT (proc==SYMLINK);
3264 if (proc!=SYMLINK || line[TRACE_VERSION_POS]!='2')
3265 add_new_file_system_object(proc, dep_index, line, reply_line);
3268 //end_profile (&add_create_object_profile);
3271 inline void add_new_file_system_object (int proc, int dep_index, char * line, char * reply_line)
3273 char * child_trace_fh;
3274 fh_map_t * parent_entryp;
3275 char component_name[MAX_PLAY_PATH_SIZE];
3276 char * parent_trace_fh;
3277 char child_path[MAX_PLAY_PATH_SIZE];
3278 post_op_fh3 * post_op_fh3_child;
3279 char * reply_trace_fh;
3280 nfs_fh3 * child_fh3;
3282 parent_trace_fh = strstr (line, "fh");
3283 RFS_ASSERT (parent_trace_fh);
3284 parent_trace_fh +=3;
3285 parent_entryp = lookup_fh (parent_trace_fh);
3286 RFS_ASSERT (parent_entryp);
3287 parse_name (parent_trace_fh+65, component_name);
3288 strcpy (child_path, parent_entryp->path);
3289 strcat (child_path, "/");
3290 strcat (child_path, component_name);
3292 /* find the corresponding create request */
3293 //printf ("before find reply trace_fh reply_line %s\n", reply_line);
3294 #ifdef REDUCE_MEMORY_TRACE_SIZE
3295 reply_trace_fh = dep_tab[dep_index].reply_trace_fh;
3297 reply_trace_fh = find_reply_trace_fh (reply_line);
3299 RFS_ASSERT (reply_trace_fh != NULL);
3302 RFS_ASSERT (((CREATE3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3303 child_fh3 = &((CREATE3res *)arg_res)->res_u.ok.obj.handle;
3306 RFS_ASSERT (((MKDIR3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3307 child_fh3 = &((MKDIR3res *)arg_res)->res_u.ok.obj.handle;
3310 RFS_ASSERT (((SYMLINK3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3311 child_fh3 = &((SYMLINK3res *)arg_res)->res_u.ok.obj.handle;
3314 RFS_ASSERT (((MKNOD3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3315 child_fh3 = &((MKNOD3res *)arg_res)->res_u.ok.obj.handle;
3318 RFS_ASSERT (proc==LOOKUP);
3319 child_fh3 = &((LOOKUP3res *)arg_res)->res_u.ok.object;
3324 #ifndef REDUCE_MEMORY_TRACE_SIZE
3325 RFS_ASSERT (reply_trace_fh[TRACE_FH_SIZE]==' ');
3327 reply_trace_fh[TRACE_FH_SIZE] = 0;
3328 add_fh (FH_MAP_FLAG_COMPLETE, reply_trace_fh, child_path, child_fh3); /* exist flag is not used now, set to 1 */
3329 #ifndef REDUCE_MEMORY_TRACE_SIZE
3330 /* just to preserve the original reply line not changed */
3331 reply_trace_fh[TRACE_FH_SIZE] = ' ';
3335 /* initialize timestamp and proc field of dep_tab entry */
3336 void trace_play(void)
3339 /* The flag to indicate whether trace_player is BUSY. Trace_player is BUSY
3340 * when either there is request to send or there is reply being
3341 * received. Otherwise it is IDLE. The timeout for polling replies
3342 * is set to 0 when BUSY, it is set to the waiting time to the first
3343 * request outside of current <min_dep_index, dep_window_max> window when IDLE.
3345 int busy_flag = BUSY;
3346 //int dep_index; /* index into dependency table: dep_tab */
3347 //int biod_index; /* index into outstanding requests: biod_reqp */
3349 disk_io_status = read_trace();
3350 RFS_ASSERT (!CYCLIC_EMPTY(dep_tab_index));
3351 CYCLIC_MOVE_HEAD(dep_window_index);
3353 adjust_play_window(busy_flag, &poll_timeout);
3355 start_profile (&total_profile);
3356 while (!CYCLIC_EMPTY(dep_tab_index)) {
3357 if ((total_profile.in.tv_sec > 600)) {
3358 printf ("the process has run for more than 600 seconds, exit\n");
3362 if (busy_flag == IDLE) {
3363 //start_profile (&check_timeout_profile);
3365 //end_profile (&check_timeout_profile);
3366 if (disk_io_status!=TRACE_FILE_END) {
3367 disk_io_status = read_trace();
3371 //start_profile (&adjust_play_window_profile);
3372 adjust_play_window (busy_flag, &poll_timeout);
3374 printf("num_out_reqs %d\n", num_out_reqs);
3376 //end_profile (&adjust_play_window_profile);
3378 start_profile (&execute_next_request_profile);
3379 while (execute_next_request()!=-1) {
3382 end_profile (&execute_next_request_profile);
3385 start_profile (&receive_next_reply_profile);
3386 /* actually the performance of two policy seems to be same */
3387 //#define SEND_HIGHER_PRIORITY_POLICY
3388 #define SEND_RECEIVE_EQUAL_PRIORITY_POLICY
3390 #ifdef SEND_HIGHER_PRIORITY_POLICY
3391 receive_next_reply(IDLE);
3393 #ifdef SEND_RECEIVE_EQUAL_PRIORITY_POLICY
3395 while (receive_next_reply(busy_flag)!=-1)
3398 end_profile (&receive_next_reply_profile);
3402 end_profile (&total_profile);
3404 RFS_ASSERT (disk_io_status == TRACE_FILE_END);
3405 if (num_out_reqs !=0 ) {
3406 printf ("num_out_reqs %d\n", num_out_reqs);
3407 CYCLIC_PRINT(dep_tab_index);
3409 RFS_ASSERT(num_out_reqs==0);
3412 printf ("trace starttime %d, trace_end_time %d trace_duration %d\n", trace_timestamp1, trace_timestamp2,
3413 trace_timestamp2 - trace_timestamp1);
3414 printf ("can_not_catch_speed_num_total %d can_not_catch_speed_num_last_10_seconds %d",
3415 can_not_catch_speed_num_total, can_not_catch_speed_num);
3416 printf ("total_profile.about: %s\n", total_profile.about);
3417 print_profile ("total_profile", &total_profile);
3419 //print_profile ("check_timeout", &check_timeout_profile);
3421 //print_profile ("adjust_play_window", &adjust_play_window_profile);
3423 print_profile ("execute_next_request_profile", &execute_next_request_profile);
3424 print_profile ("valid_get_nextop_profile", &valid_get_nextop_profile);
3425 print_profile ("invalid_get_nextop_profile", &invalid_get_nextop_profile);
3426 print_profile ("prepare_argument_profile", &prepare_argument_profile);
3427 print_profile ("biod_clnt_call_profile", &biod_clnt_call_profile);
3429 print_profile ("receive_next_reply_profile", &receive_next_reply_profile);
3430 print_profile ("valid_poll_and_get_reply_profile", &valid_poll_and_get_reply_profile);
3431 print_profile ("invalid_poll_and_get_reply_profile", &invalid_poll_and_get_reply_profile);
3432 print_profile ("decode_reply_profile", &decode_reply_profile);
3433 print_profile ("check_reply_profile", &check_reply_profile);
3434 print_profile ("fgets_profile", &fgets_profile);
3435 print_profile ("read_line_profile", &read_line_profile);
3436 print_profile ("read_trace_profile", &read_trace_profile);
3437 //print_profile ("add_create_object", &add_create_object_profile);
3440 printf ("dep_tab_index.tail %d dep_tab_index.head %d num_out_reqs %d\n", dep_tab_index.tail, dep_tab_index.head, num_out_reqs);
3443 int CYCLIC_SET_TAIL_TO(cyclic_index_t * index, int dest)
3445 cyclic_index_t indextmp, indextmp2;
3448 indextmp2 = indextmp;
3449 oldnum = CYCLIC_NUM(indextmp);
3451 if (! ((dest>=0) && (dest<indextmp.size))) {
3452 CYCLIC_PRINT(indextmp);
3453 printf("dest %d\n", dest);
3455 RFS_ASSERT ((dest>=0) && (dest<indextmp.size));
3457 indextmp2.tail = dest;
3458 num = CYCLIC_NUM(indextmp2);
3461 CYCLIC_PRINT(indextmp);
3462 CYCLIC_PRINT(indextmp2);
3463 printf("dest %d old_num %d num %d\n", dest, oldnum, num);
3465 RFS_ASSERT (num <= oldnum);
3471 for (i=0; i<500; i++) {
3472 printf ("*************************************************************\n");
3477 int CYCLIC_ASSERT (int i)
3480 if (!(dep_tab_index.tail == dep_window_index.tail)) {
3481 printf("%s head %d tail %d, size %d\n", dep_tab_index.name, dep_tab_index.head, dep_tab_index.tail, dep_tab_index.size);
3482 printf("%s head %d tail %d, size %d\n", dep_window_index.name, dep_window_index.head, dep_window_index.tail, dep_window_index.size);
3483 printf("pos %d\n", i);
3489 if (!((dep_window_index.head == dep_tab_index.head) ||
3490 CYCLIC_LESS(dep_tab_index, dep_window_index.head, dep_tab_index.head ) )) {
3491 printf("%s head %d tail %d, size %d\n", dep_tab_index.name, dep_tab_index.head, dep_tab_index.tail, dep_tab_index.size);
3492 printf("%s head %d tail %d, size %d\n", dep_window_index.name, dep_window_index.head, dep_window_index.tail, dep_window_index.size);
3493 printf("pos %d\n", i);
3498 for (i=0, j=0; i<max_biod_reqs; i++) {
3499 if (biod_reqp[i].in_use == 1)
3502 RFS_ASSERT (num_out_reqs==j);
3504 RFS_ASSERT ((dep_window_index.head == dep_tab_index.head) ||
3505 CYCLIC_LESS(dep_tab_index, dep_window_index.head, dep_tab_index.head ));