1 /* Try to change thread scheduling and uses three threads */
3 static char sfs_c_chdSid[] = "@(#)sfs_c_chd.c 2.1 97/10/23";
7 * Copyright (c) 1992-1997,2001 by Standard Performance Evaluation Corporation
9 * Standard Performance Evaluation Corporation (SPEC)
10 * 6585 Merchant Place, Suite 100
13 * This product contains benchmarks acquired from several sources who
14 * understand and agree with SPEC's goal of creating fair and objective
15 * benchmarks to measure computer performance.
17 * This copyright notice is placed here only to protect SPEC in the
18 * event the source is misused in any manner that is contrary to the
19 * spirit, the goals and the intent of SPEC.
21 * The source code is provided to the user or company under the license
22 * agreement for the SPEC Benchmark Suite for this product.
25 /*****************************************************************
27 * Copyright 1991,1992 Legato Systems, Inc. *
28 * Copyright 1991,1992 Auspex Systems, Inc. *
29 * Copyright 1991,1992 Data General Corporation *
30 * Copyright 1991,1992 Digital Equipment Corporation *
31 * Copyright 1991,1992 Interphase Corporation *
32 * Copyright 1991,1992 Sun Microsystems, Inc. *
34 *****************************************************************/
37 * -------------------------- sfs_c_chd.c -------------------------
39 * The sfs child. Routines to initialize child parameters,
40 * initialize test directories, and generate load.
43 * void child(int, float, int, char *);
44 * void init_fileinfo(void);
45 * void init_counters(void);
46 * sfs_fh_type * randfh(int, int, uint_t, sfs_state_type,
48 * int check_access(struct *stat)
49 * int check_fh_access();
52 * void check_call_rate(void);
53 * void init_targets(void);
54 * void init_dirlayout(void);
55 * void init_rpc(void);
56 * void init_testdir(void);
61 * 21-Aug-92 Wittle randfh() uses working set files array.
62 * init_fileinfo() sets up working set.
63 * 02-Jul-92 Teelucksingh Target file size now based on peak load
65 * 04-Jan-92 Pawlowski Added raw data dump hooks.
66 * 16-Dec-91 Wittle Created.
71 * ------------------------- Include Files -------------------------
84 #include <sys/types.h>
89 #include "sfs_c_def.h"
90 #include "sfs_m_def.h"
91 #include "rfs_c_def.h"
92 #include "generic_hash.h"
93 #include "nfsd_nfsfh_cust.h"
95 extern struct hostent *Server_hostent;
97 #define PROB_SCALE 1000L
98 #define _M_MODULUS 2147483647L /* (2**31)-1 */
100 #define _GROUP_DIVISOR 500
101 #define _FILES_PER_GROUP 4
102 #define _MIN_GROUPS 12
103 #define _WORKING_SET_AT_25_OPS_PER_SEC 975
107 * ----------------------- External Definitions -----------------------
109 extern uint32_t biod_clnt_call(CLIENT *, uint32_t, xdrproc_t, void *);
110 extern enum clnt_stat proc_header(CLIENT *cl, xdrproc_t xdr_results, void *results_ptr);
111 extern int biod_poll_wait(CLIENT *, uint32_t);
112 extern enum clnt_stat get_areply_udp (CLIENT * cl, uint32_t *xid, struct timeval *timeout);
113 extern char * parse_name (char * t, char * buf);
115 /* forward definitions for local functions */
116 static int init_rpc(void);
118 /* RFS: forward definitions for local functions */
120 static void init_signal();
121 extern void init_file_system (void);
122 extern void init_dep_tab (void);
123 static int read_trace(void);
124 static void read_fh_map();
125 static void init_play (char * mount_point);
126 static void trace_play(void);
127 void print_result(void);
128 static int get_nextop(void);
129 static int check_timeout(void);
130 static struct biod_req * get_biod_req(int dep_tab_index);
131 static int lookup_biod_req (int xid);
132 static void init_time_offset(void);
133 void adjust_play_window (int flag, int * poll_timeout_arg);
134 static int poll_and_get_reply (int usecs);
135 static char * nfs3_strerror(int status);
136 static void check_clock(void);
137 static double time_so_far1(void);
138 static double get_resolution(void);
139 static void usage(void);
140 void init_dep_tab_entry (int dep_index);
141 extern inline fh_map_t * lookup_fh (char * trace_fh );
142 static void finish_request (int biod_index, int dep_index, int status, int dep_flag);
143 static inline void add_new_file_system_object (int proc, int dep_index, char * line, char * reply_line);
144 static inline char * find_lead_trace_fh(int proc, char * line);
145 static inline char * find_reply_trace_fh (char * line);
148 * ------------- Per Child Load Generation Rate Variables -----------
150 static uint_t Calls_this_period; /* calls made during the current run period */
151 static uint_t Calls_this_test; /* calls made during the test so far */
152 static uint_t Reqs_this_period; /* reqs made during the current run period */
153 static uint_t Reqs_this_test; /* reqs made during the test so far */
154 static uint_t Sleep_msec_this_test; /* msec slept during the test so far */
155 static uint_t Sleep_msec_this_period;
156 static uint_t Previous_chkpnt_msec; /* beginning time of current run period */
157 static int Target_sleep_mspc; /* targeted sleep time per call */
159 static char io_buf[BUFSIZ]; /* io buffer for print out messages */
162 int Log_fd; /* log fd */
163 char Logname[NFS_MAXNAMLEN]; /* child processes sync logfile */
164 int Validate = 0; /* fake variable */
165 int Child_num = 0; /* fake: child index */
166 int Tcp = 0; /* We implement UDP first */
167 int Client_num = 1; /* fake: number of client */
171 /* as long as the inital value is different, then it's OK */
177 int no_progress_flag = 0;
178 int num_out_reqs_statistics[MAX_OUTSTANDING_REQ+1];
179 int num_out_reqs_statistics_at_timeout[MAX_OUTSTANDING_REQ+1];
182 * ------------------------- SFS Child -------------------------
185 static int nfs2proc_to_rfsproc[18] = {0, 1, 2, 3, 4, 5, 6, 7, 8, 9,
186 10, 11, 12, 13, 14, 15, 16, 17};
187 static int nfs3proc_to_rfsproc[NFS3_PROCEDURE_COUNT] = {0, 1, 2, 4, 18, 5, 6, 8, 9, 14,
188 13, 21, 10, 15, 11, 12, 16, 23, 17, 20,
190 void print_usage(int pos, int argc, char ** argv)
193 printf("sfs3 hostname:mount_dir trace_file|stdin fh_map_file play_scale warmup_time(in seconds) \n");
194 printf("sfs3 -pair_trace trace_file\n");
195 printf("sfs3 -pair_write trace_file\n");
196 printf("sfs3 -help\n");
197 printf ("pos %d argc %d", pos, argc);
198 for (i=0; i<argc; i++) {
199 printf(" %s", argv[i]);
205 void print_cyclic_buffers ()
207 CYCLIC_PRINT(memory_trace_index);
208 CYCLIC_PRINT(dep_tab_index);
209 CYCLIC_PRINT(dep_window_index);
212 void add_to_dep_tab(int i)
215 fh_map_t * fh_map_entry;
218 trace_fh = strstr (memory_trace[i].line, "fh");
220 printf ("memory_trace[%d].line %s\n", i, memory_trace[i].line);
221 RFS_ASSERT (trace_fh);
223 fh_map_entry = lookup_fh (trace_fh);
224 if (fh_map_entry && (fh_map_entry->flag==FH_MAP_FLAG_DISCARD) ) {
225 req_num_with_discard_fh ++;
229 req_num_with_init_fh ++;
231 req_num_with_new_fh ++;
233 RFS_ASSERT (!CYCLIC_FULL(dep_tab_index));
234 ent = &(dep_tab[dep_tab_index.head]);
236 ent->disk_index = memory_trace[i].disk_index;
237 ent->memory_index = i;
238 #ifdef REDUCE_MEMORY_TRACE_SIZE
239 ent->trace_status = memory_trace[i].trace_status;
240 ent->reply_trace_fh = memory_trace[i].reply_trace_fh;
242 ent->line = memory_trace[i].line;
243 init_dep_tab_entry(dep_tab_index.head);
245 if (rfs_debug && (i%100000)==0)
246 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);
247 CYCLIC_MOVE_HEAD(memory_trace_index);
248 CYCLIC_MOVE_HEAD(dep_tab_index);
251 void init_profile_variables ()
253 init_profile ("total_profile", &total_profile);
254 init_profile ("execute_next_request_profile", &execute_next_request_profile);
255 init_profile ("valid_get_nextop_profile", &valid_get_nextop_profile);
256 init_profile ("invalid_get_nextop_profile",&invalid_get_nextop_profile);
257 init_profile ("prepare_argument_profile", &prepare_argument_profile);
258 init_profile ("biod_clnt_call_profile", &biod_clnt_call_profile);
259 init_profile ("receive_next_reply_profile", &receive_next_reply_profile);
260 init_profile ("valid_poll_and_get_reply_profile", &valid_poll_and_get_reply_profile);
261 init_profile ("invalid_poll_and_get_reply_profile", &invalid_poll_and_get_reply_profile);
262 init_profile ("decode_reply_profile", &decode_reply_profile);
263 init_profile ("check_reply_profile", &check_reply_profile);
264 init_profile ("add_create_object_profile", &add_create_object_profile);
265 init_profile ("check_timeout_profile", &check_timeout_profile);
266 init_profile ("adjust_play_window_profile",&adjust_play_window_profile);
267 init_profile ("fgets_profile",&fgets_profile);
268 init_profile ("read_line_profile",&read_line_profile);
269 init_profile ("read_trace_profile",&read_trace_profile);
272 static char trace_file[256]="anon-lair62-011130-1200.txt";
273 int print_memory_usage()
275 printf("size of fh_map_t %d size of fh_map %d\n", sizeof(fh_map_t), sizeof(fh_map));
276 printf("sizeof dep_tab_t %d sizeof dep_tab %d\n", sizeof(dep_tab_t), sizeof(dep_tab));
277 printf("size of memory_trace_ent_t %d sizeof memory_trace %d\n", sizeof(memory_trace_ent_t), sizeof(memory_trace));
278 printf("size of CREATE3args %d\n", sizeof( CREATE3args));
279 printf("size of MKDIR3args %d\n", sizeof( MKDIR3args));
280 printf("size of READ3args %d\n", sizeof( READ3args));
281 printf("size of WRITE3args %d\n", sizeof( WRITE3args));
282 printf("size of RENAME3args %d\n", sizeof( RENAME3args));
283 printf("size of GETATTR3args %d\n", sizeof( GETATTR3args));
284 printf("size of SETATTR3args %d\n", sizeof( SETATTR3args));
285 printf("size of LINK3args %d\n", sizeof( LINK3args));
286 printf("size of SYMLINK3args %d\n", sizeof( SYMLINK3args));
287 printf("size of MKNOD3args %d\n", sizeof( MKNOD3args));
288 printf("size of RMDIR3args %d\n", sizeof( RMDIR3args));
289 printf("size of REMOVE3args %d\n", sizeof( REMOVE3args));
290 printf("size of LOOKUP3args %d\n", sizeof( LOOKUP3args));
291 printf("size of READDIR3args %d\n", sizeof( READDIR3args));
292 printf("size of READDIRPLUS3args %d\n", sizeof( READDIRPLUS3args));
293 printf("size of FSSTAT3args %d\n", sizeof( FSSTAT3args));
294 printf("size of FSINFO3args %d\n", sizeof( FSINFO3args));
295 printf("size of COMMIT3args %d\n", sizeof( COMMIT3args));
296 printf("size of ACCESS3args %d\n", sizeof( ACCESS3args));
297 printf("size of READLINK3args %d\n", sizeof( READLINK3args));
304 int last_print_time = -1;
307 while (send_num ==0) {
311 //while (!CYCLIC_EMPTY(dep_tab_index)) {
313 if ((total_profile.in.tv_sec - last_print_time >= 10)) {
314 static int recv_num_before_10_seconds = 0;
315 last_print_time = total_profile.in.tv_sec;
316 fprintf (stdout, "<<<<< recv_thread recv_num %d time %d num_out_reqs %d \n", recv_num, total_profile.in.tv_sec, num_out_reqs);
317 if (recv_num == recv_num_before_10_seconds) {
318 no_progress_flag = 1;
321 recv_num_before_10_seconds = recv_num;
323 //start_profile (&check_timeout_profile);
325 //end_profile (&check_timeout_profile);
329 start_profile (&receive_next_reply_profile);
330 /* actually the performance of two policy seems to be same */
331 //#define SEND_HIGHER_PRIORITY_POLICY
332 #define SEND_RECEIVE_EQUAL_PRIORITY_POLICY
333 #ifdef SEND_HIGHER_PRIORITY_POLICY
334 receive_next_reply(IDLE);
336 #ifdef SEND_RECEIVE_EQUAL_PRIORITY_POLICY
338 while (receive_next_reply(busy_flag)!=-1) {
342 end_profile (&receive_next_reply_profile);
344 printf ("<<<< recv thread EXIT\n");
350 /* number of seconds the I/O thread pauses after each time trying to read the requests */
351 #define IO_THREAD_PAUSE_TIME 1
356 disk_io_status = read_trace ();
357 while (disk_io_status == TRACE_BUF_FULL) {
361 printf("&&&&&&&&&& io thread, sleep %d seconds\n", j/100);
364 disk_io_status = read_trace ();
365 //printf ("io_thread, after read_trace, disk_index %d\n", disk_index);
368 for (i=0; i<SEQUEN_READ_NUM; i++) {
369 add_to_dep_tab(CYCLIC_MINUS(memory_trace_index.head,1,memory_trace_index.size));
372 //printf ("***************** IO THREAD SLEEP 1 s\n");
373 //print_cyclic_buffers();
376 RFS_ASSERT (disk_io_status == TRACE_FILE_END);
377 printf("io_thread EXIT\n");
383 struct timeval playstart_time, playend_time;
385 sleep (10); /* first let io_thread to run for a while */
386 printf ("trace_play\n");
388 gettimeofday(&playstart_time, NULL);
393 gettimeofday(&playend_time, NULL);
397 sec = playend_time.tv_sec - playstart_time.tv_sec;
398 usec = sec * 1000000 + (playend_time.tv_usec - playstart_time.tv_usec);
399 sec = usec / 1000000;
400 usec = usec % 1000000;
401 printf("Total play time: %d sec %d usec\n", sec, usec);
402 if (sec > WARMUP_TIME)
405 printf ("the trace play time %d is less than WARMUP_TIME %d, no statistical results\n");
409 while (exit_flag == 1) {
414 clnt_destroy(NFS_client);
423 pthread_t io_thread_var;
425 pthread_t recv_thread_var;
427 pthread_t execute_thread_var;
429 ret = pthread_attr_init (&attr);
431 perror("pthread_attr_init attr");
435 ret = pthread_create (&(io_thread_var), &attr, &io_thread, (void *)&arg );
437 perror("io_pthread_attr_init");
443 ret = pthread_create (&(recv_thread_var), &attr, &recv_thread, (void *)&arg );
445 perror("recv_pthread_attr_init");
451 ret = pthread_create (&(execute_thread_var), &attr, &execute_thread, (void *)&arg );
453 perror("io_pthread_attr_init");
461 CYCLIC_INIT("memory_trace_index",memory_trace_index,MAX_MEMORY_TRACE_LINES);
462 CYCLIC_INIT("dep_tab_index ",dep_tab_index,DEP_TAB_SIZE);
463 CYCLIC_INIT("dep_window_index ",dep_window_index,DEP_TAB_SIZE);
466 int main(int argc, char ** argv)
468 extern char * optarg;
470 struct timeval in={1000000, 100};
472 init_profile_variables();
473 if ((argc==1) || (argc==2 && !strcmp(argv[1],"-help"))) {
474 print_usage(0, argc, argv);
477 if (!strcmp(argv[1], "-pair_write")) {
479 strcpy(trace_file, argv[2]);
481 strcpy(trace_file, "stdin");
482 pair_write(trace_file);
485 if (!strcmp(argv[1], "-pair_trace")) {
487 strcpy(trace_file, argv[2]);
489 strcpy(trace_file, "stdin");
490 pair_trace(trace_file);
493 if (!strcmp(argv[1], "-check_aging")) {
495 print_usage(3, argc, argv);
498 strcpy(trace_file, argv[2]);
499 check_aging (trace_file);
502 if (!strcmp(argv[1], "-check_statistics")) {
504 print_usage(1, argc, argv);
507 strcpy(trace_file, argv[2]);
508 memset(fh_htable, 0, sizeof (fh_htable));
509 check_statistics (trace_file);
514 print_usage(2, argc, argv);
518 PLAY_SCALE = atoi (argv[4]);
519 RFS_ASSERT (PLAY_SCALE >=1 && PLAY_SCALE <=10000);
521 WARMUP_TIME = atoi (argv[5]);
522 RFS_ASSERT (WARMUP_TIME >=0 && WARMUP_TIME <=1000);
524 print_memory_usage();
526 getmyhostname(lad_hostname, HOSTNAME_LEN);
530 * Get the uid and gid information.
537 Nfs_timers = Nfs_udp_timers;
543 //init_play ("capella:/p5/RFSFS");
545 read_fh_map (argv[3]);
546 //read_fh_map ("fh-path-map-play");
547 strcpy(trace_file, argv[2]);
549 /* If ordered by TIMESTAMP,
550 * memory_trace_index.tail <= dep_tab_index.tail < dep_window_max <=
551 * dep_tab_index.head <= memory_trace_index.head
554 init_global_variables();
561 int init_global_variables()
563 memset (num_out_reqs_statistics, 0, sizeof(num_out_reqs_statistics));
564 memset (num_out_reqs_statistics_at_timeout, 0, sizeof(num_out_reqs_statistics_at_timeout));
567 int init_semaphores()
569 async_rpc_sem = dest_and_init_sem (ASYNC_RPC_SEM_KEY, 1, "async_rpc_sem");
575 nfs_version = NFS_V3;
578 /* Set up the signal handlers for all signals */
581 #if (defined(_XOPEN_SOURCE) || defined(USE_POSIX_SIGNALS))
582 struct sigaction sig_act, old_sig_act;
584 /* use XOPEN signal handling */
586 sig_act.sa_handler = generic_catcher;
587 (void)sigemptyset(&sig_act.sa_mask);
588 sig_act.sa_flags = 0;
590 /* signals handlers for signals used by sfs */
591 sig_act.sa_handler = sfs_cleanup;
592 if (sigaction(SIGINT,&sig_act,&old_sig_act) == -1) {
593 perror("sigaction failed: SIGINT");
597 sig_act.sa_handler = sfs_cleanup;
598 if (sigaction(SIGTERM,&sig_act,&old_sig_act) != 0) {
599 perror("sigaction failed: SIGTERM");
603 /* signals handlers for signals used by sfs */
604 (void) signal(SIGINT, sfs_cleanup);
605 // RFS (void) signal(SIGALRM, sfs_alarm);
606 (void) signal(SIGTERM, sfs_cleanup);
612 char * mount_point) /* Mount point for remote FS */
614 char namebuf[NFS_MAXNAMLEN] = "trace_play"; /* unique name for this program */
615 CLIENT * mount_client_ptr; /* Mount client handle */
618 (void) setvbuf(stderr, io_buf, _IOLBF, BUFSIZ);
620 sfs_Myname = namebuf;
623 * May require root priv to perform bindresvport operation
625 mount_client_ptr = lad_getmnt_hand(mount_point);
626 if (mount_client_ptr == NULL) {
631 * should be all done doing priv port stuff
634 if (init_rpc() == -1) {
635 (void) fprintf(stderr, "%s: rpc initialization failed\n", sfs_Myname);
636 (void) generic_kill(0, SIGINT);
642 * finish all priv bindresvport calls
645 if (setuid(Real_uid) != (uid_t)0) {
646 (void) fprintf(stderr,"%s: %s%s", sfs_Myname,
647 "cannot perform setuid operation.\n",
648 "Do `make install` as root.\n");
651 init_mount_point(0, mount_point, mount_client_ptr);
655 * Cleanup client handle for mount point
657 clnt_destroy(mount_client_ptr);
662 #ifdef REDUCE_MEMORY_TRACE_SIZE
663 void inline format_line (char * line_before, char * line)
665 char * pv = line_before;
670 //printf("format_line before %s\n", line_before);
671 p = strstr (pv, "fh");
682 RFS_ASSERT ((*pv >='0' && *pv <='9') || (*pv >='a' && *pv<='f'));
686 RFS_ASSERT ((i==48) || (i==40) || (i==24));
691 p = strstr (pv, "fh");
693 while ((*pv)!='\0') {
696 //printf("format_line after %s\n", line);
699 char * read_line (int disk_index)
701 static FILE * fp=NULL;
703 static int start_disk_index=0;
705 static int finish_flag = 0;
706 static int varfh_flag = 0;
707 #define READ_LINE_BUF_SIZE (MAX_COMMAND_REPLY_DISTANCE_FOR_PAIR+2)
708 #define SAFE_BYTES 1000
709 #define READ_LINE_LENGTH (MAX_TRACE_LINE_LENGTH+SAFE_BYTES)
711 static char line_buf[READ_LINE_BUF_SIZE][READ_LINE_LENGTH];
712 char varfh_line_buf[READ_LINE_LENGTH];
714 start_profile (&read_line_profile);
717 if (strcmp(trace_file, "stdin")) {
718 fp = fopen(trace_file, "r");
720 if (strstr(trace_file, ".varfh")) {
723 if (strstr(trace_file, ".fmt1")) {
724 TRACE_COMMAND_REPLY_FLAG_POS += 12;
725 TRACE_VERSION_POS +=12;
726 TRACE_MSGID_POS +=12;
730 printf("can not open files %s\n", fp);
736 RFS_ASSERT (fp!=NULL);
737 for (i=0; i<READ_LINE_BUF_SIZE; i++) {
738 start_profile(&fgets_profile);
740 if (!fgets(varfh_line_buf, READ_LINE_LENGTH, fp)) {
743 format_line (varfh_line_buf, line_buf[i]);
745 if (!fgets(line_buf[i], READ_LINE_LENGTH, fp)) {
749 end_profile(&fgets_profile);
750 //printf ("read_line, line_buf[%d]:%s", i, line_buf[i]);
754 if (disk_index > start_disk_index+READ_LINE_BUF_SIZE) {
755 printf ("disk_index %d start_disk_index %d READ_LINE_BUF_SIZE %d\n",
756 disk_index, start_disk_index, READ_LINE_BUF_SIZE);
758 RFS_ASSERT (disk_index <= start_disk_index+READ_LINE_BUF_SIZE)
759 if (disk_index==(start_disk_index+READ_LINE_BUF_SIZE)) {
763 start_profile(&fgets_profile);
764 if (!fgets(line_buf[start], READ_LINE_LENGTH, fp)) {
765 end_profile(&fgets_profile);
769 end_profile(&fgets_profile);
770 //printf ("read_line, line_buf[%d]:%s", start, line_buf[start]);
771 start = (start+1) % READ_LINE_BUF_SIZE;
774 RFS_ASSERT (disk_index < start_disk_index+READ_LINE_BUF_SIZE)
775 i = (start+disk_index-start_disk_index)%READ_LINE_BUF_SIZE;
778 if (!(strlen(line_buf[i])>80)) {
779 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]);
780 RFS_ASSERT (strlen(line_buf[i])>80);
782 if (!((strlen(line_buf[i])>80) && (strlen(line_buf[i])<MAX_TRACE_LINE_LENGTH)))
783 printf ("disk_index %d strlen %d line_buf[%d] %s\n", disk_index, strlen(line_buf[i]), i, line_buf[i]);
784 RFS_ASSERT ((strlen(line_buf[i])>80) && (strlen(line_buf[i])<MAX_TRACE_LINE_LENGTH));
787 end_profile (&read_line_profile);
788 return (line_buf[i]);
791 #define OPS_FLAG_INC 0
792 #define OPS_FLAG_PRINT 1
793 int read_write_fh_statistics (int flag, char * buf, int timestamp)
795 static FILE * fp = NULL;
799 fp = fopen ("read_write_fh.output", "w");
802 if (flag == OPS_FLAG_INC) {
803 p = strstr (buf, "fh");
807 fprintf(fp, "%s\n", p+3+24);
810 if (flag == OPS_FLAG_PRINT) {
811 int disk_index = (int) buf;
812 fprintf(fp, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
816 int write_statistics(int flag, char * buf, char * reply_buf, int trace_status)
818 static FILE * fp = NULL;
819 int pre_size, size, count;
820 char * p = reply_buf;
822 fp = fopen ("write.output", "w");
825 if (flag == OPS_FLAG_INC) {
826 p = strstr (p, "pre-size");
828 sscanf (p, "pre-size %x", &pre_size);
829 p += strlen("pre-size");
830 p = strstr (p, "size");
832 sscanf (p, "size %x", &size);
833 p = strstr (p, "count");
835 fprintf (fp, "%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
837 sscanf (p, "count %x", &count);
838 fprintf (fp, "%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
840 if (flag == OPS_FLAG_PRINT) {
841 int disk_index = (int) buf;
842 int timestamp = (int) reply_buf;
843 fprintf(fp, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
847 void ops_statistics (int ops_flag, int proc, int timestamp)
849 static FILE * fp = NULL;
855 } ops[NOPS]={{0, 0, 0, "NULL"},{0, 0, 0, "GETATTR"},{0, 0, 1, "SETATTR"},{0, 0, 0, "ROOT"},
856 {0, 0, 0, "LOOKUP"},{0, 0, 0, "READLINK"},{0, 0, 0, "READ"},{0, 0, 1, "WRCACHE"},
857 {0, 0, 1, "WRITE"}, {0, 0, 1, "CREATE"},{0, 0, 1, "REMOVE"},{0, 0, 1, "RENAME"},
858 {0, 0, 1, "LINK"}, {0, 0, 1, "SYMLINK"},{0, 0, 1, "MKDIR"},{0, 0, 1, "RMDIR"},
859 {0, 0, 0, "READDIR"},{0, 0, 0, "FSSTAT"},{0, 0, 0, "ACCESS"},{0, 0, 0, "COMMIT"},
860 {0, 0, 0, "FSINFO"},{0, 0, 1, "MKNOD"}, {0, 0, 0, "PATHCONF"}, {0, 0, 0, "READDIRPLUS"}};
862 if (ops_flag == OPS_FLAG_INC) {
863 RFS_ASSERT (proc>=0 && proc<NOPS);
865 if (ops[proc].count == 1000) {
866 ops[proc].count_K ++;
870 if (ops_flag == OPS_FLAG_PRINT) {
872 int update_K=0, update=0, total_K=0, total=0;
874 int disk_index = proc;
877 fp = fopen ("mix.output", "w");
880 for (i=0; i<NOPS; i++) {
881 total_K += ops[i].count_K;
882 total += ops[i].count;
883 if (ops[i].update_flag) {
884 update_K += ops[i].count_K;
885 update += ops[i].count;
888 update_K += update/1000;
889 update = update%1000;
890 total_K += total/1000;
895 for (i=0; i<NOPS; i++) {
897 f2 = f2*1000+ops[i].count;
898 fprintf (fp, "%12s %8d,%03d %3.2f\%\n", ops[i].name, ops[i].count_K, ops[i].count, f2*100/f1);
899 fprintf (stderr, "%12s %8d,%03d %3.2f\%\n", ops[i].name, ops[i].count_K, ops[i].count, f2*100/f1);
903 fprintf (fp, " total %8d,%03d\n", total_K, total);
904 fprintf (stderr, " total %8d,%03d\n", total_K, total);
905 fprintf (fp, " update %8d,%03d %2.2f\%\n", update_K, update, f2*100/f1);
906 fprintf (stderr, " update %8d,%03d %2.2f\%\n", update_K, update, f2*100/f1);
907 fprintf(fp, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
908 fprintf(stderr, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
913 void truncate_statistics (int flag, int proc, char * buf, char * reply_buf)
915 #define TRACE_FH_SIZE2 16
916 #define BLOCK_SIZE 4096
917 static int no_size_num = 0;
918 static int have_size_num = 0;
919 static int equal_size_num = 0;
920 static int first_size_num = 0;
921 static int truncate_num = 0;
922 static int truncate_size = 0;
923 static int truncate_KB = 0;
924 static int truncate_block_num = 0;
925 static int padding_num = 0;
926 static int padding_KB = 0;
927 static int padding_size = 0;
928 static FILE * fp = NULL;
931 int pre_size, size, count;
932 struct generic_entry * ent;
934 if (flag == OPS_FLAG_PRINT) {
935 int disk_index = proc;
936 int timestamp = (int)buf;
938 fp = fopen ("truncate.output", "w");
941 truncate_KB += truncate_size/1000;
942 truncate_size %= 1000;
943 padding_KB += padding_size/1000;
944 padding_size %= 1000;
945 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);
946 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);
950 p = strstr (&buf[TRACE_MSGID_POS], "fh");
956 p = strstr (buf, " size ");
958 RFS_ASSERT (proc==WRITE);
959 p = strstr (reply_buf, " ftype 1 ");
961 p = strstr (p, " size ");
963 if (strstr(p, " ftype 1 ")) {
964 fprintf (fp, "#### %s%s\n", buf, reply_buf);
965 fprintf (stderr, "#### %s%s\n", buf, reply_buf);
967 RFS_ASSERT (!strstr(p, " ftype 1 "));
975 sscanf (p, " size %x", &size);
976 if (size <0 || size > 2000000000) {
977 fprintf (fp, "#### size too big %x %s %s\n", size, buf, reply_buf);
978 fprintf (stderr, "#### size too big %x %s %s\n", size, buf, reply_buf);
981 RFS_ASSERT (size >=0 && size <2000000000);
982 ent = generic_lookup (trace_fh+24, TRACE_FH_SIZE2, 0, fh_htable, FH_HTABLE_SIZE);
984 if (ent->key3 != size) {
986 //printf ("%s\n", buf);
987 //printf ("size change fh %s pre-size %x size %x\n", trace_fh, ent->key3, size);
988 if (ent->key3 > size) {
990 truncate_size += ent->key3 - size;
991 truncate_block_num += (ent->key3+BLOCK_SIZE-1)/BLOCK_SIZE;
993 //fprintf (stderr, "truncate: pre_size %x size %x %s\n", ent->key3, size, buf);
994 //fprintf (fp, "truncate: pre_size %x size %x %s\n", ent->key3, size, buf);
995 truncate_block_num -= (size + BLOCK_SIZE-1)/BLOCK_SIZE;
997 if (truncate_size > 1000000000) {
998 truncate_KB += truncate_size/1000;
999 truncate_size %= 1000;
1003 //printf ("%s\n", buf);
1004 //printf ("padding fh %s pre-size %x size %x\n", trace_fh, ent->key3, size);
1005 padding_size += size - ent->key3;
1006 if (padding_size > 1000000000) {
1007 padding_KB += padding_size/1000;
1008 padding_size %= 1000;
1016 generic_insert(trace_fh+24, TRACE_FH_SIZE2, size, fh_htable, FH_HTABLE_SIZE);
1021 int get_timestamp_usec (char * buf)
1025 strncpy(str, buf, 100);
1026 RFS_ASSERT (str[10]=='.');
1027 RFS_ASSERT (str[17]==' ');
1029 ret = atoi(&str[11]);
1030 RFS_ASSERT (ret >=0 && ret <=999999);
1034 int get_timestamp_sec (char * buf)
1038 strncpy(str, buf, 100);
1039 RFS_ASSERT (str[10]=='.');
1042 RFS_ASSERT (ret >1000000000 && ret <2000000000);
1046 int check_aging (char * tracefile)
1054 int nfs3proc, msgid, proc;
1056 while ((buf=read_line(++disk_index))!=NULL) {
1057 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1059 if (buf[TRACE_VERSION_POS]!='3')
1061 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1063 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1065 proc = nfs3proc_to_rfsproc[nfs3proc];
1066 ops_statistics (OPS_FLAG_INC, proc, -1);
1069 int off, count, size;
1071 case CREATE: printf("%s\n", "create"); break;
1072 case MKDIR: printf("%s\n", "mkdir"); break;
1073 case REMOVE: printf("%s\n", "remove"); break;
1074 case RMDIR: printf("%s\n", "rmdir"); break;
1077 t = strstr (t, "off");
1080 sscanf (t, "%x", &off);
1081 RFS_ASSERT (off>=0 && off<0x7FFFFFFF)
1082 t = strstr (t, "count");
1085 sscanf (t, "%x", &count);
1086 RFS_ASSERT (count <= 32768);
1087 printf("%s off %x count %x\n", "write", off, count);
1088 //printf("%s count %x\n", "write", count);
1091 t = strstr (buf, " size ");
1093 sscanf (t, " size %x", &size);
1094 printf ("%s size %x\n", "setattr", size);
1097 if ((disk_index%10000)==0) {
1098 fprintf(stderr, "%d disk trace passed\n", disk_index);
1102 fprintf(stderr, "%d disk trace parsed\n", disk_index);
1103 ops_statistics (OPS_FLAG_PRINT, disk_index, -1);
1107 int check_statistics (char * tracefile)
1116 int nfs3proc, msgid, proc;
1117 static int last_timestamp_sec = -1;
1119 int memory_trace_size = 0;
1121 while ((buf=read_line(++disk_index))!=NULL) {
1122 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1124 if (buf[TRACE_VERSION_POS]!='3')
1126 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1128 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1129 timestamp_sec = get_timestamp_sec(buf);
1131 proc = nfs3proc_to_rfsproc[nfs3proc];
1132 ops_statistics (OPS_FLAG_INC, proc, -1);
1134 if (proc!= WRITE && proc!=SETATTR && proc!=READ) {
1137 RFS_ASSERT (buf[strlen(buf)-1]=='\n');
1138 buf [strlen(buf)-1] = 0;
1139 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
1140 printf("disk_index %d strlen(buf) %d buf %s \n", disk_index, strlen(buf), buf);
1141 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
1143 printf("read line disk_index %d %s\n", disk_index, buf);
1145 trace_status = NFS3ERR_RFS_MISS;
1146 for (i=disk_index+1; i<disk_index+MAX_COMMAND_REPLY_DISTANCE; i++) {
1147 reply_buf = read_line(i);
1149 printf("searching for reply: read line %s\n", reply_buf);
1152 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1153 p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
1155 if (!strncmp(&reply_buf[TRACE_MSGID_POS], &buf[TRACE_MSGID_POS], p-&(reply_buf[TRACE_MSGID_POS]))) {
1156 trace_status = find_reply_status(reply_buf);
1157 if (trace_status == NFS3_OK) {
1158 if (proc==READ || proc==WRITE)
1159 read_write_fh_statistics (OPS_FLAG_INC, buf, 0);
1161 write_statistics (OPS_FLAG_INC, buf, reply_buf, trace_status);
1162 if (proc==WRITE || proc==SETATTR)
1163 truncate_statistics (OPS_FLAG_INC, proc, buf, reply_buf);
1168 //if (memory_trace[memory_trace_size].trace_status == NFS3ERR_RFS_MISS)
1169 if (trace_status == NFS3ERR_RFS_MISS) {
1170 //printf ("%s no reply\n", buf);
1171 missing_reply_num ++;
1174 #if 0 /* commented out by G. Jason Peng */
1176 if ((missing_reply_num > memory_trace_size/10) && (missing_reply_num > 100)) {
1177 printf ("missing_reply_num %d too high for memory_trace_size %d\n", missing_reply_num, memory_trace_size);
1182 memory_trace_size ++;
1184 if (last_timestamp_sec == -1) {
1185 last_timestamp_sec = timestamp_sec;
1186 } else if (timestamp_sec - last_timestamp_sec >=3600) {
1187 ops_statistics (OPS_FLAG_PRINT, disk_index, timestamp_sec);
1188 truncate_statistics (OPS_FLAG_PRINT, disk_index, (char *)timestamp_sec, NULL);
1189 read_write_fh_statistics(OPS_FLAG_PRINT, (char *)disk_index, timestamp_sec);
1190 write_statistics(OPS_FLAG_PRINT, (char *)disk_index, (char *)timestamp_sec, -1);
1191 last_timestamp_sec = timestamp_sec;
1194 if ((memory_trace_size%10000)==0) {
1195 fprintf(stderr, "%d disk trace parsed, missing_reply %d\n", disk_index, missing_reply_num);
1196 ops_statistics (OPS_FLAG_PRINT, -1);
1197 truncate_statistics (OPS_FLAG_PRINT, -1, NULL, NULL);
1202 fprintf(stderr, "%d disk trace parsed, missing_reply %d\n", disk_index, missing_reply_num);
1203 ops_statistics (OPS_FLAG_PRINT, disk_index, timestamp_sec);
1204 truncate_statistics (OPS_FLAG_PRINT, disk_index, (char *)timestamp_sec, NULL);
1205 read_write_fh_statistics(OPS_FLAG_PRINT, (char *)disk_index, timestamp_sec);
1206 write_statistics(OPS_FLAG_PRINT, (char *)disk_index, (char *)timestamp_sec, -1);
1210 /* This routine output all the requests, together with their replies */
1211 int pair_trace (char * tracefile)
1220 int nfs3proc, msgid;
1221 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};
1222 int memory_trace_size = 0;
1224 char output_file[1024];
1226 strcpy (output_file, tracefile);
1227 strcat (output_file, ".pair");
1228 outputfp = fopen (output_file, "w");
1229 RFS_ASSERT (outputfp);
1231 while ((buf=read_line(++disk_index))!=NULL) {
1232 if (disk_index == 258)
1234 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1236 if (buf[TRACE_VERSION_POS]!='3')
1238 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1240 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1243 buf [strlen(buf)-1] = 0;
1244 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
1245 printf("disk_index %d strlen(buf) %d buf %s \n", disk_index, strlen(buf), buf);
1246 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
1248 printf("read line disk_index %d %s\n", disk_index, buf);
1249 fprintf (outputfp, "%s\n", buf);
1251 trace_status = NFS3ERR_RFS_MISS;
1252 for (i=disk_index+1; i<disk_index+MAX_COMMAND_REPLY_DISTANCE_FOR_PAIR; i++) {
1253 reply_buf = read_line(i);
1255 printf("searching for reply: read line %s\n", reply_buf);
1258 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1259 p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
1261 if (!strncmp(&reply_buf[TRACE_MSGID_POS], &buf[TRACE_MSGID_POS], p-&(reply_buf[TRACE_MSGID_POS]))) {
1262 fprintf(outputfp, "%s", reply_buf);
1263 trace_status = find_reply_status(reply_buf);
1265 fprintf(stderr, "reply found trace_status %d\n", find_reply_status(reply_buf));
1271 if (trace_status == NFS3ERR_RFS_MISS) {
1272 fprintf (stderr, "%s no reply\n", buf);
1273 fprintf(outputfp, "missing_reply\n");
1274 missing_reply_num ++;
1277 if (missing_reply_num > memory_trace_size/10 && missing_reply_num >100) {
1278 fprintf (stderr, "missing_reply_num %d too high for memory_trace_size %d\n", missing_reply_num, memory_trace_size);
1282 memory_trace_size ++;
1284 if ((memory_trace_size%10000)==0)
1285 fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, memory_trace_size, missing_reply_num );
1288 fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, memory_trace_size, missing_reply_num );
1289 //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);
1292 /* This routine output all the write requests, together with their replies. It is used for
1293 * analysis of write requests: appended bytes, overwrite bytes etc
1295 int pair_write (char * tracefile)
1303 int pair_write_debug = 0;
1304 int nfs3proc, msgid;
1305 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};
1306 int memory_trace_size = 0;
1308 while ((buf=read_line(++disk_index))!=NULL) {
1309 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1311 if (buf[TRACE_VERSION_POS]!='3')
1313 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1315 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1318 if (!strstr(buf, "write"))
1321 buf [strlen(buf)-1] = 0;
1322 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
1323 printf("disk_index %d strlen(buf) %d buf %s \n", disk_index, strlen(buf), buf);
1324 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
1325 if (pair_write_debug)
1326 printf("read line disk_index %d %s\n", disk_index, buf);
1328 /* store the request to memory */
1329 //strcpy (memory_trace[memory_trace_size].line, buf);
1330 //memory_trace[memory_trace_size].disk_index = disk_index;
1332 /* find and store the reply status and reply fhandle to memory */
1333 //memory_trace[memory_trace_size].trace_status = NFS3ERR_RFS_MISS;
1334 trace_status = NFS3ERR_RFS_MISS;
1335 for (i=disk_index+1; i<disk_index+MAX_COMMAND_REPLY_DISTANCE_FOR_PAIR; i++) {
1336 reply_buf = read_line(i);
1337 if (pair_write_debug)
1338 printf("searching for reply: read line %s\n", reply_buf);
1341 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1342 p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
1344 if (!strncmp(&reply_buf[TRACE_MSGID_POS], &buf[TRACE_MSGID_POS], p-&(reply_buf[TRACE_MSGID_POS]))) {
1345 int pre_size, size, count;
1346 //memory_trace[memory_trace_size].trace_status = find_reply_status(reply_buf);
1347 if (pair_write_debug)
1348 printf("reply found trace_status %d\n", find_reply_status(reply_buf));
1350 trace_status = find_reply_status(reply_buf);
1351 if (trace_status == NFS3_OK) {
1352 p = strstr (p, "pre-size");
1354 sscanf (p, "pre-size %x", &pre_size);
1355 p += strlen("pre-size");
1356 p = strstr (p, "size");
1358 sscanf (p, "size %x", &size);
1359 p = strstr (p, "count");
1361 printf ("%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
1363 sscanf (p, "count %x", &count);
1364 printf ("%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
1370 //if (memory_trace[memory_trace_size].trace_status == NFS3ERR_RFS_MISS)
1371 if (trace_status == NFS3ERR_RFS_MISS) {
1372 printf ("%s no reply\n", buf);
1373 missing_reply_num ++;
1376 #if 0 /* commented out by G. Jason Peng */
1377 if (missing_reply_num > memory_trace_size/10) {
1378 printf ("missing_reply_num %d too high for memory_trace_size %d\n", missing_reply_num, memory_trace_size);
1383 memory_trace_size ++;
1386 if (memory_trace_size >= MAX_MEMORY_TRACE_LINES) {
1387 fprintf (stderr, "memory trace size %d is not enough\n", MAX_MEMORY_TRACE_LINES);
1391 if ((memory_trace_size%10000)==0)
1392 fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, memory_trace_size, missing_reply_num );
1395 fprintf(stderr, "total %d disk lines %d memory lines missing_reply_num %d\n", disk_index, memory_trace_size, missing_reply_num );
1396 //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);
1401 /* This function is not finished writing */
1402 int calculate_performance()
1411 struct timeval start;
1412 struct timeval stop;
1415 } trace_performance_ent_t;
1417 struct timeval req_time;
1418 struct timeval reply_time;
1420 trace_performance_ent_t * ent = NULL;
1422 while (!CYCLIC_FULL(memory_trace_index)) {
1424 if (ent!=NULL && (ent->trace_status == NFS3ERR_RFS_MISS))
1426 if ((buf=read_line(++disk_index))==NULL) {
1427 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 );
1428 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);
1429 end_profile (&read_trace_profile);
1430 return TRACE_FILE_END;
1433 get_timestamp (&ent->req_time, buf);
1434 if (MAX_COMMAND_REPLY_DISTANCE ==1) {
1435 ent->trace_status == NFS3ERR_RFS_MISS;
1437 reply_buf=read_line(++disk_index);
1438 RFS_ASSERT (reply_buf);
1439 if (!strcmp(reply_buf, "missing_reply\n")) {
1440 ent->trace_status == NFS3ERR_RFS_MISS;
1442 get_timestamp (&ent->reply_time, buf);
1443 ent->trace_status = find_reply_status(reply_buf);
1457 memory_trace_ent_t * ent=NULL;
1459 start_profile (&read_trace_profile);
1461 while (!CYCLIC_FULL(memory_trace_index)) {
1462 if (ent!=NULL && (ent->trace_status == NFS3ERR_RFS_MISS))
1464 if ((buf=read_line(++disk_index))==NULL) {
1465 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 );
1466 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);
1467 end_profile (&read_trace_profile);
1468 return TRACE_FILE_END;
1472 printf ("disk_index %d %s\n", disk_index, buf);
1474 if (disk_index==0) {
1475 trace_timestamp1 = get_timestamp_sec (buf);
1476 trace_starttime.sec = get_timestamp_sec (buf);
1477 trace_starttime.usec = get_timestamp_usec (buf);
1478 trace_starttime.esec = 0;
1479 printf ("trace starttime %d %d %d\n", trace_starttime.sec, trace_starttime.usec, trace_starttime.esec);
1481 trace_timestamp2 = get_timestamp_sec (buf);
1483 /* store the request to memory */
1484 ent = &(memory_trace[memory_trace_index.head]);
1485 strcpy (ent->line, buf);
1486 ent->disk_index = disk_index;
1488 if (MAX_COMMAND_REPLY_DISTANCE ==1) {
1489 ent->trace_status == NFS3ERR_RFS_MISS;
1491 reply_buf=read_line(++disk_index);
1492 RFS_ASSERT (reply_buf);
1493 if (!strcmp(reply_buf, "missing_reply\n")) {
1494 ent->trace_status == NFS3ERR_RFS_MISS;
1496 ent->trace_status = find_reply_status(reply_buf);
1500 if (ent->trace_status == NFS3ERR_RFS_MISS)
1501 missing_reply_num ++;
1503 if (MAX_COMMAND_REPLY_DISTANCE > 1) {
1504 if ((missing_reply_num > disk_index/5) && (missing_reply_num > 100)) {
1505 printf ("missing_reply_num %d too high for disk_index %d\n", missing_reply_num, disk_index);
1510 /* find and store the reply trace fhandle for create-class requests */
1511 if (ent->trace_status==NFS3_OK) {
1512 if (strstr(buf, "create") || strstr(buf, "mkdir")
1513 || (strstr(buf, "symlink") && (buf[TRACE_VERSION_POS]!='2'))
1514 || strstr(buf, "mknod") ) {
1515 p = find_reply_trace_fh(reply_buf);
1517 printf("skip line disk_index %d %s \n", disk_index, buf);
1520 memcpy(ent->reply_trace_fh, p, TRACE_FH_SIZE);
1522 memset(ent->reply_trace_fh, 0, TRACE_FH_SIZE);
1525 add_to_dep_tab(memory_trace_index.head);
1527 if (((disk_index+1)%20000)==0) {
1528 fprintf(stderr, "%d disk trace parsed \n", disk_index+1);
1532 end_profile (&read_trace_profile);
1533 return TRACE_BUF_FULL;
1535 #else /* not defined REDUCE_MEMORY_TRACE_SIZE */
1543 fp = fopen(trace_file, "r");
1544 RFS_ASSERT (fp!=NULL);
1545 while (fgets(buf, MAX_TRACE_LINE_LENGTH, fp)) {
1546 if (!((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH)))
1547 printf("strlen(buf) %d buf %s \n", strlen(buf), buf);
1548 RFS_ASSERT ((strlen(buf)>80) && (strlen(buf)<MAX_TRACE_LINE_LENGTH));
1550 /* store the request to memory */
1551 strcpy (memory_trace[memory_trace_size].line, buf);
1552 memory_trace[memory_trace_size].disk_index = disk_index;
1553 memory_trace_size ++;
1555 if (memory_trace_size >= MAX_MEMORY_TRACE_LINES) {
1556 fprintf (stderr, "memory trace size %d is not enough\n", MAX_MEMORY_TRACE_LINES);
1559 if ((disk_index%100000)==0)
1560 fprintf(stderr, "%d disk trace parsed, store %d trace lines to memory\n", disk_index, memory_trace_size);
1564 fprintf(stderr, "total %d disk lines %d memory lines \n", disk_index, memory_trace_size );
1569 #ifdef REDUCE_MEMORY_TRACE_SIZE
1570 inline int disk_index_to_memory_index (int disk_index)
1572 static int memory_index = 0;
1574 RFS_ASSERT (!CYCLIC_EMPTY(memory_trace_index));
1575 RFS_ASSERT (memory_trace[memory_trace_index.tail].disk_index <= disk_index);
1576 RFS_ASSERT (memory_trace[CYCLIC_MINUS(memory_trace_index.head,1,memory_trace_index.size)].disk_index >=disk_index);
1577 if (disk_index > memory_trace[memory_index].disk_index) {
1578 while (memory_trace[memory_index].disk_index < disk_index) {
1579 memory_index = CYCLIC_ADD(memory_index,1,memory_trace_index.size);
1582 if (disk_index < memory_trace[memory_index].disk_index) {
1583 while (memory_trace[memory_index].disk_index > disk_index) {
1584 memory_index = CYCLIC_MINUS(memory_index,1,memory_trace_index.size);
1588 RFS_ASSERT (disk_index == memory_trace[memory_index].disk_index);
1589 return memory_index;
1592 #define disk_index_to_memory_index(disk_index) disk_index
1595 #define get_line_by_disk_index(disk_index) \
1596 memory_trace[disk_index_to_memory_index(disk_index)].line
1598 inline char * find_reply_line (char * command_line, int cur_disk_index)
1603 int request_memory_index = disk_index_to_memory_index (cur_disk_index);
1604 for (i=request_memory_index+1; i<request_memory_index+MAX_COMMAND_REPLY_DISTANCE && i<MAX_MEMORY_TRACE_LINES; i++) {
1605 line = memory_trace[i].line;
1606 if (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1607 p = strchr (&line[TRACE_MSGID_POS], ' ');
1609 if (!strncmp(&line[TRACE_MSGID_POS], &command_line[TRACE_MSGID_POS], p-&(line[TRACE_MSGID_POS])))
1616 inline int find_reply_status (char * line)
1622 printf ("line %s flag %c\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
1623 if (!(line[TRACE_COMMAND_REPLY_FLAG_POS]=='R')) {
1624 printf ("disk_index %d %s\n", disk_index, line);
1626 RFS_ASSERT (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R');
1627 p = line+TRACE_MSGID_POS+2; /* at least one letter for msgid and one letter for space */
1628 if (strstr(p, "OK"))
1630 if (strstr(p, "lookup 2") || strstr(p, "lookup 2"))
1632 if (strstr(p, "create d"))
1634 if (strstr(p, "setattr 1"))
1636 if (strstr(p, "setattr 2712")) /* 10002 NFS3ERR_NOT_SYNC */
1638 if (strstr(p, "lookup d"))
1640 if (strstr(p, "read d"))
1642 if (strstr(p, "write d"))
1644 if (strstr(p, "write 46"))
1646 if (strstr(p, "getattr 46"))
1648 if (strstr(p, "mkdir d"))
1650 printf ("line %s flag %c return value weird\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
1651 printf ("!!!!!!!!!!!!!!!!!!!!!!!!\n");
1652 fprintf (stderr, "line %s flag %c return value weird\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
1653 fprintf (stderr, "!!!!!!!!!!!!!!!!!!!!!!!!\n");
1656 inline int find_reply_status_old (char * line)
1661 //printf ("line %s flag %c\n", line, line[TRACE_COMMAND_REPLY_FLAG_POS]);
1662 RFS_ASSERT (line[TRACE_COMMAND_REPLY_FLAG_POS]=='R');
1663 if (!strstr(line, "OK")) {
1664 p=strstr(line, " 6 read ");
1666 p+=strlen(" 6 read ");
1668 p = strstr (line, "status=XXX");
1671 RFS_ASSERT (*p==' ');
1679 sscanf (p, "%x", &i);
1680 if ((i<=0) || (i>10000))
1681 printf("line %s\n", line);
1682 RFS_ASSERT (i>0 && i<10009);
1687 inline char * find_reply_trace_fh (char * line)
1690 p = strstr (line, "OK fh");
1692 printf ("disk_index %d find_reply_trace_fh line %s\n", disk_index, line);
1698 #ifndef NO_DEPENDENCY_TABLE
1699 inline int disk_index_to_dep_index(int cur_dep_index, int disk_index)
1702 for (i=cur_dep_index; i>min_dep_index; i--) {
1703 if (dep_tab[i].disk_index == disk_index)
1710 inline int is_play_candidate (int dep_index)
1712 int proc = dep_tab[dep_index].proc;
1713 int status = dep_tab[dep_index].status;
1714 int trace_status = dep_tab[dep_index].trace_status;
1716 #ifndef TAKE_CARE_CREATE_MODE_BY_DAN
1717 /* for a failed create in trace, trace_replay just ignore many time the trace create fail
1718 * due to access control, but trace_play will success because our access control
1719 * may be loose (all uid/gid is mapped to single one 513:513, so we just skip these requests
1721 if ((proc==CREATE || proc==MKDIR) && (trace_status!=NFS3_OK) && (status!=NFS3ERR_RFS_MISS)) {
1722 if (dependency_debug)
1723 printf ("disk[%d] ignore failed create/mkdir in trace, trace_status %d line %s",
1724 dep_tab[dep_index].disk_index, trace_status, dep_tab[dep_index].line);
1725 failed_create_command_num ++;
1729 #ifndef TAKE_CARE_OTHER_FAILED_COMMAND
1730 if (((trace_status == NFS3ERR_ACCES) && (proc==READ || proc==WRITE || proc==LOOKUP)) ||
1731 ((trace_status == NFS3ERR_PERM) && (proc==SETATTR)) ){
1732 if (dependency_debug)
1733 printf ("disk[%d] ignore other failed command in trace, trace_status %d line %s",
1734 dep_tab[dep_index].disk_index, trace_status, dep_tab[dep_index].line);
1736 failed_other_command_num ++;
1740 #ifndef TAKE_CARE_SYMBOLIC_LINK
1741 if ((dep_tab[dep_index].proc==READLINK) ) { /* send request */
1742 skipped_readlink_command_num ++;
1746 /* This is actually take care in get_nextop by checking fh_map error when dep_index==min_dep_index */
1747 #ifndef TAKE_CARE_CUSTOM_COMMAND
1748 /* this line has a file handle which should belong to discard but it is not
1749 * the file handle directly appears as parent directory in a lookup request
1750 * the return value is NOENT, the parent directory should have been initialized
1751 * but the initialization code just ignored all lookup request which didn't success
1752 * including NOENT even though the parent directory is still valid.
1755 if (( ((dep_tab[dep_index].disk_index==262213) || (dep_tab[dep_index].disk_index==214402))
1756 && !(strcmp(trace_file, "anon-lair62-011130-1100.txt"))
1758 ( ((dep_tab[dep_index].disk_index==238460) || (dep_tab[dep_index].disk_index ==238470))
1759 && !(strcmp(trace_file, "anon-lair62-011130-1000.txt"))
1761 skipped_custom_command_num++;
1765 if (( ((dep_tab[dep_index].disk_index==423727) || (0))
1766 && !(strncmp(trace_file, "anon-lair62-011130-1500.txt", strlen("anon-lair62-011130-1500.txt")))
1768 ( ((dep_tab[dep_index].disk_index==238460) || (dep_tab[dep_index].disk_index ==238470))
1769 && !(strcmp(trace_file, "anon-lair62-011130-1000.txt"))
1771 skipped_custom_command_num++;
1774 /* this line is about the mkdir 116d9d originally in anon-lair62-011130-1400.txt */
1775 if (!strncmp(dep_tab[dep_index].line, "1007147245.194201", strlen("1007147245.194201"))) {
1776 skipped_custom_command_num++;
1780 #ifndef TAKE_CARE_FSSTAT_COMMAND
1781 /* the file handle used in this command is not processed properly by pre-processing */
1783 char * trace_fh = find_lead_trace_fh(proc, dep_tab[dep_index].line);
1784 fh_map_t * fh = lookup_fh (trace_fh);
1786 skipped_fsstat_command_num++;
1794 inline int is_dir_op (int proc)
1811 inline int is_create_op (int proc)
1813 if (proc==CREATE || proc==MKDIR || proc==LINK || proc==SYMLINK || proc==MKNOD || proc==RENAME)
1818 inline int is_delete_op (int proc)
1820 if (proc==REMOVE || proc==RMDIR || proc==RENAME)
1825 static inline char * find_lead_trace_fh(int proc, char * line)
1828 /* check the file handle availability */
1829 p = strstr (line, "fh");
1831 p+=3; //printf ("check dependency dep_tab[%d] trace_fh %s line %s \n", dep_index, trace_fh, line);
1835 inline char * find_another_trace_fh(int proc, char * line)
1838 /* check the file handle availability */
1839 p = strstr (line, "fh2");
1841 p+=4; //printf ("check dependency dep_tab[%d] trace_fh %s line %s \n", dep_index, trace_fh, line);
1845 /* return the index of next request in dep_tab.
1846 * Return -1 if there is no suitable request to send
1848 inline int get_nextop(void)
1852 static int dep_index = -2;
1855 #define INIT_MIN_WAIT_VALUE -999
1856 static int min_wait_fhandle_dep_index = INIT_MIN_WAIT_VALUE;
1860 if (min_wait_fhandle_dep_index == -999)
1861 min_wait_fhandle_dep_index = dep_window_index.head;
1863 for (i=0; i<CYCLIC_NUM(dep_window_index); i++) {
1864 dep_index = (dep_window_index.tail+i) % dep_window_index.size;
1866 proc = dep_tab[dep_index].proc;
1867 flag = dep_tab[dep_index].flag;
1869 if (dependency_debug)
1870 printf ("get_nextop check dep_tab[%d].disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
1871 #ifdef NO_DEPENDENCY_TABLE
1872 if (dep_tab[dep_index].flag == DEP_FLAG_INIT) {
1873 if (is_play_candidate(dep_index)==TRUE) {
1874 /* the trace_fh is the file handle for the operation directory, trace_fh_2 is other file handle
1875 * used in the request */
1876 if (proc==LINK || proc==RENAME) {
1877 dep_tab[dep_index].trace_fh = find_another_trace_fh (proc, dep_tab[dep_index].line);
1878 dep_tab[dep_index].trace_fh_2 = find_lead_trace_fh(proc, dep_tab[dep_index].line);
1879 dep_tab[dep_index].fh = 0;
1880 dep_tab[dep_index].fh_2 = 0;
1882 dep_tab[dep_index].trace_fh = find_lead_trace_fh(proc, dep_tab[dep_index].line);
1883 dep_tab[dep_index].fh = 0;
1884 dep_tab[dep_index].fh_2 = (fh_map_t *)1;
1886 dep_tab[dep_index].flag = DEP_FLAG_CANDIDATE;
1888 dep_tab[dep_index].skip_sec = skip_sec;
1890 if (dependency_debug)
1891 printf ("disk[%d] state DEP_FLAG_INIT to DEP_FLAG_CANDIDATE\n", dep_tab[dep_index].disk_index);
1893 if (dependency_debug)
1894 printf ("disk[%d] state DEP_FLAG_INIT to DEP_FLAG_DONE\n", dep_tab[dep_index].disk_index);
1895 dep_tab[dep_index].flag = DEP_FLAG_DONE;
1900 if ((dep_tab[dep_index].flag == DEP_FLAG_CANDIDATE) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_FHANDLE) ) {
1902 if (!dep_tab[dep_index].fh)
1903 dep_tab[dep_index].fh = lookup_fh (dep_tab[dep_index].trace_fh);
1904 if (!dep_tab[dep_index].fh_2)
1905 dep_tab[dep_index].fh_2 = lookup_fh (dep_tab[dep_index].trace_fh_2);
1907 /* need to wait for file handle */
1908 if ((!dep_tab[dep_index].fh) || (!dep_tab[dep_index].fh_2)) {
1909 if (dependency_debug)
1910 printf("disk[%d] can not lookup file handle\n", dep_tab[dep_index].disk_index);
1911 if (dep_tab[dep_index].flag == DEP_FLAG_CANDIDATE) {
1912 if (dependency_debug)
1913 printf ("disk[%d] state DEP_FLAG_CANDIDATE to DEP_FLAG_WAIT_FHANDLE\n", dep_tab[dep_index].disk_index);
1914 dep_tab[dep_index].flag = DEP_FLAG_WAIT_FHANDLE;
1915 sfs_gettime (&dep_tab[dep_index].start);
1916 if (CYCLIC_LESS(dep_tab_index,dep_index,min_wait_fhandle_dep_index))
1917 min_wait_fhandle_dep_index = dep_index;
1920 if (dep_index==dep_window_index.tail) {
1922 printf ("fh_path_map error disk[%d] state DEP_FLAG_WAIT_FHANDLE to DEP_FLAG_DONE\n", dep_tab[dep_index].disk_index);
1923 fh_path_map_err_num ++;
1924 dep_tab[dep_index].flag = DEP_FLAG_DONE;
1928 SUBTIME (tmp, dep_tab[dep_index].start);
1929 #define DEPENDENCY_TIMEOUT 50
1931 RFS_ASSERT (tmp.sec < DEPENDENCY_TIMEOUT + (skip_sec - dep_tab[dep_index].skip_sec));
1933 if (tmp.sec >= DEPENDENCY_TIMEOUT) {
1934 printf("dep_tab[%d].flag %d disk_index %d line %s\n", dep_index,
1935 dep_tab[dep_index].flag, dep_tab[dep_index].disk_index,
1936 dep_tab[dep_index].line);
1938 RFS_ASSERT (tmp.sec < DEPENDENCY_TIMEOUT );
1944 /* file handle ready, adjust_min_wait_fhandle_dep_index */
1945 if ((dep_tab[dep_index].flag == DEP_FLAG_WAIT_FHANDLE)) {
1946 if (dep_index == min_wait_fhandle_dep_index) {
1947 min_wait_fhandle_dep_index = dep_window_index.head;
1948 for (j=CYCLIC_ADD(dep_index,1,dep_window_index.size); CYCLIC_LESS(dep_window_index,j,dep_window_index.head); j++) {
1949 if (dep_tab[j].flag ==DEP_FLAG_WAIT_FHANDLE) {
1950 min_wait_fhandle_dep_index = j;
1956 if (dependency_debug)
1957 printf("disk[%d] found file handle\n", dep_tab[dep_index].disk_index);
1958 dep_tab[dep_index].flag = DEP_FLAG_FHANDLE_READY;
1960 /* the normal file operation can be executed now */
1961 if (!is_dir_op (dep_tab[dep_index].proc)) {
1962 if (dependency_debug)
1963 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
1967 if (dependency_debug)
1968 printf("disk[%d] directory operation \n", dep_tab[dep_index].disk_index);
1969 /* the directory operation need to lock the directory first */
1970 if (dep_tab[dep_index].fh->lock) {
1971 if (dependency_debug)
1972 printf ("disk[%d] state %d to DEP_FLAG_WAIT_DIRECTORY\n", dep_tab[dep_index].disk_index, dep_tab[dep_index].flag);
1973 dep_tab[dep_index].flag = DEP_FLAG_WAIT_DIRECTORY;
1978 if ((dep_tab[dep_index].flag == DEP_FLAG_FHANDLE_READY) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_DIRECTORY)) {
1979 int j = dep_tab[dep_index].fh - fh_map;
1980 if (dependency_debug) {
1981 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);
1982 printf ("trace_fh %s path %s\n", dep_tab[dep_index].fh->trace_fh, dep_tab[dep_index].fh->path);
1983 printf ("trace_fh %s path %s\n", fh_map[j].trace_fh, fh_map[j].path);
1985 if ((dep_tab[dep_index].fh->lock) || ((proc==RENAME) && (dep_tab[dep_index].fh_2->lock)) ) {
1986 if (dependency_debug)
1987 printf ("continue to wait for directory lock\n");
1990 if (dependency_debug)
1991 printf ("dep_tab[%d] disk index %d LOCK fh_map[%d] \n", dep_index, dep_tab[dep_index].disk_index, j);
1992 dep_tab[dep_index].fh->lock = 1;
1994 dep_tab[dep_index].fh_2->lock = 1;
1996 /* the non-delete directory operation can proceed now */
1997 if (!is_delete_op (dep_tab[dep_index].proc)) {
1998 if (dependency_debug)
1999 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
2003 /* the delete operation can proceed if nobody ahead is waiting for fhandle */
2004 /* probably this condition is not strong enough */
2005 // if ((min_wait_fhandle_dep_index<dep_index) ) {
2006 if (dep_index!=dep_window_index.tail) {
2007 if (dependency_debug)
2008 printf ("disk[%d] state %d to DEP_FLAG_WAIT_DELETE\n", dep_tab[dep_index].disk_index, dep_tab[dep_index].flag);
2009 dep_tab[dep_index].flag = DEP_FLAG_WAIT_DELETE;
2012 dep_tab[dep_index].flag = DEP_FLAG_DIRECTORY_READY;
2015 if ((dep_tab[dep_index].flag == DEP_FLAG_DIRECTORY_READY) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_DELETE)) {
2016 // if (min_wait_fhandle_dep_index > dep_index) {
2017 if (dep_index==dep_window_index.tail) {
2018 if (dependency_debug)
2019 printf ("return disk[%d]\n", dep_tab[dep_index].disk_index);
2023 #else /*NO_DEPENDENCY_TABLE undefined */
2024 /* this part of code will be invalid after CYCLIC buffer design */
2025 if (dep_tab[dep_index].flag == DEP_FLAG_INIT){
2026 for (j=0, t=&(dep_tab[dep_index].dep_ops[0]);
2027 (j<dep_tab[dep_index].init_dep_num) && (dep_tab[dep_index].cur_dep_num>0);
2030 if (dep_tab[disk_index_to_dep_index(dep_index, *t)].flag == DEP_FLAG_DONE) {
2031 /* The depended request has been finished */
2033 dep_tab[dep_index].cur_dep_num --;
2038 if (dep_tab[dep_index].cur_dep_num == 0) {
2045 if (dependency_debug)
2046 printf ("get_nexop return -1\n");
2050 int check_timeout(void)
2052 static int biod_index = 0;
2054 int dep_index; /* index into dep_tab */
2056 sfs_op_type *op_ptr; /* per operation info */
2057 struct ladtime timeout;
2058 struct ladtime current_time;
2060 sfs_gettime (¤t_time);
2062 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
2063 if (biod_reqp[biod_index].in_use==TRUE) {
2064 timeout = biod_reqp[biod_index].timeout;
2065 if ((current_time.sec>timeout.sec) ||
2066 ((current_time.sec==timeout.sec) && (current_time.usec>timeout.usec))) {
2068 dep_index = biod_reqp[biod_index].dep_tab_index;
2069 proc = dep_tab[dep_index].proc;
2070 op_ptr = &Ops[proc];
2071 op_ptr->results.timeout_calls++;
2072 Ops[TOTAL].results.timeout_calls++;
2075 if (is_create_op(proc)) {
2076 dep_tab[dep_index].flag = DEP_FLAG_CANDIDATE;
2077 printf ("resend dep_tab[%d], disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
2078 finish_request (biod_index, dep_index, NFS3ERR_RFS_TIMEOUT, DEP_FLAG_CANDIDATE);
2080 finish_request (biod_index, dep_index, NFS3ERR_RFS_TIMEOUT, DEP_FLAG_DONE);
2083 num_out_reqs_statistics_at_timeout[num_out_reqs]++;
2085 //RFS_ASSERT (!is_create_op(proc));
2087 if (per_packet_debug)
2088 printf ("timeout request: disk_index %d, dep_index %d biod_reqp[%d].start %d:%d timeout %d:%d current %d:%d\n", dep_tab[dep_index].disk_index, dep_index, biod_index, biod_reqp[biod_index].start.sec, biod_reqp[biod_index].start.usec, timeout.sec, timeout.usec, current.sec, current.usec);
2094 /* Allocate a biod_req entry to send and receive request dep_tab[dep_index]
2095 * build the cross reference between dep_tab entry and biod_req entry
2097 struct biod_req * get_biod_req(int dep_index) /* index into dep_tab */
2099 static int biod_index = 0;
2101 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
2102 if (!biod_reqp[biod_index].in_use) {
2103 biod_reqp[biod_index].in_use = 1;
2104 biod_reqp[biod_index].dep_tab_index = dep_index;
2105 dep_tab[dep_index].biod_req_index = biod_index;
2107 return &(biod_reqp[biod_index]);
2113 /* Return index into biod_reqp
2114 * return -1 upon failure
2116 int lookup_biod_req (int xid)
2118 static int biod_index = 0;
2120 for (i=0; i<max_biod_reqs; i++, biod_index = (biod_index+1)%max_biod_reqs) {
2121 /* give a NULL as timeout pointer may cause indefinitely block */
2122 if ((biod_reqp[biod_index].in_use == TRUE) &&( biod_reqp[biod_index].xid == xid)) {
2129 extern struct ladtime test_start;
2130 void init_time_offset(void)
2132 struct ladtime tmp1;
2133 struct ladtime tmp2;
2136 test_start.usec = 0;
2137 sfs_gettime (&tmp1); /* called at initial time: tmp1 = play_starttime */
2139 DIVTIME (tmp1, PLAY_SCALE) /* tmp1 = play_starttime / SCALE */
2142 MULTIME (tmp1, PLAY_SCALE) /* tmp1 = play_starttime * SCALE */
2145 tmp2 = trace_starttime; /* tmp2 = trace_starttime */
2146 SUBTIME (tmp2, tmp1); /* tmp2 = trace_starttime - play_starttime *|/ SCALE */
2147 time_offset = tmp2; /* time_offset = trace_starttime - play_starttime *|/ SCALE */
2150 /* initialize timestamp and proc field of dep_tab entry */
2151 void init_dep_tab_entry (int dep_index)
2158 //line = get_line_by_disk_index (dep_tab[dep_index].disk_index);
2159 line = dep_tab[dep_index].line;
2160 sscanf (line, "%d.%d", &(dep_tab[dep_index].timestamp.tv_sec), &(dep_tab[dep_index].timestamp.tv_usec));
2161 sscanf (&line[TRACE_MSGID_POS], "%x %x", &msgid, &nfsproc);
2162 //printf ("msgid %x nfsproc %x\n", msgid, nfsproc);
2163 if (line[TRACE_VERSION_POS]=='2') {
2164 dep_tab[dep_index].proc = nfs2proc_to_rfsproc[nfsproc];
2165 RFS_ASSERT (nfsproc <18);
2167 /* This is for debug purpose */
2168 if (line[TRACE_VERSION_POS] !='3') {
2169 fprintf(stderr, "line[TRACE_VERSION_POS] %c line %s\n", line[TRACE_VERSION_POS], line);
2170 line = get_line_by_disk_index (dep_tab[dep_index].disk_index-1);
2172 line = get_line_by_disk_index (dep_tab[dep_index].disk_index-2);
2174 fprintf(stderr, "previousline %s\n", line);
2176 RFS_ASSERT (line[TRACE_VERSION_POS] =='3');
2177 if (nfsproc >= NFS3_PROCEDURE_COUNT) {
2178 fprintf(stderr, "proc %d line %s\n", nfsproc, line);
2181 RFS_ASSERT (nfsproc <NFS3_PROCEDURE_COUNT);
2182 dep_tab[dep_index].proc = nfs3proc_to_rfsproc[nfsproc];
2184 RFS_ASSERT (dep_tab[dep_index].proc >= 0 && dep_tab[dep_index].proc < NOPS);
2185 dep_tab[dep_index].flag = DEP_FLAG_INIT;
2188 void adjust_play_window (int flag, int * poll_timeout_arg)
2190 struct ladtime max_window_time;
2191 static struct ladtime max_poll_time = {0, 2000, 0};
2195 cyclic_index_t old_dep_window_index = dep_window_index;
2198 printf ("^^^^^^^^^^^^^^^ adjust_play_window, begin\n");
2199 CYCLIC_PRINT (dep_tab_index);
2200 printf ("dep_tab[%d].memory_index %d\n", dep_tab_index.tail, dep_tab[dep_tab_index.tail].memory_index);
2201 CYCLIC_PRINT (dep_window_index);
2202 CYCLIC_PRINT (memory_trace_index);
2203 printf (" adjust_play_window, begin\n");
2206 while ((!CYCLIC_EMPTY(dep_window_index)) && (dep_tab[dep_window_index.tail].flag == DEP_FLAG_DONE)) {
2208 //CYCLIC_PRINT (memory_trace_index);
2209 //printf("MOVE_TAIL_TO memory_index %d\n", dep_tab[dep_tab_index.tail].memory_index);
2210 RFS_ASSERT (!CYCLIC_EMPTY(memory_trace_index));
2211 RFS_ASSERT (CYCLIC_LESS (memory_trace_index, dep_tab[dep_tab_index.tail].memory_index, memory_trace_index.head));
2212 printf("%d is done\n", dep_window_index.tail);
2214 CYCLIC_MOVE_TAIL(dep_tab_index);
2215 CYCLIC_MOVE_TAIL(dep_window_index);
2218 CYCLIC_PRINT (dep_tab_index);
2219 CYCLIC_PRINT (dep_window_index);
2221 if (! (dep_tab_index.tail == dep_window_index.tail)) {
2222 CYCLIC_PRINT(dep_tab_index);
2223 CYCLIC_PRINT(dep_window_index);
2225 RFS_ASSERT ( dep_tab_index.tail == dep_window_index.tail);
2228 if (!CYCLIC_EMPTY(dep_tab_index)) {
2230 RFS_ASSERT (!CYCLIC_EMPTY(memory_trace_index));
2231 if (!(CYCLIC_LESS (memory_trace_index, dep_tab[dep_tab_index.tail].memory_index, memory_trace_index.head))) {
2232 CYCLIC_PRINT(memory_trace_index);
2233 CYCLIC_PRINT(dep_tab_index);
2234 printf("dep_tab[head-1].memory_index, %d [tail].memory_index %d\n",
2235 dep_tab[CYCLIC_MINUS(dep_tab_index.head,1,dep_tab_index.size)].memory_index,
2236 dep_tab[dep_tab_index.tail].memory_index);
2238 RFS_ASSERT (CYCLIC_LESS (memory_trace_index, dep_tab[dep_tab_index.tail].memory_index, memory_trace_index.head));
2240 CYCLIC_SET_TAIL_TO(&memory_trace_index, dep_tab[dep_tab_index.tail].memory_index);
2241 //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);
2243 // CYCLIC_MOVE_TAIL (memory_trace_index);
2247 while (CYCLIC_EMPTY(dep_tab_index)) {
2249 if (disk_io_status == TRACE_FILE_END)
2252 //printf ("************** ADJUST_PLAY_WINDOW sleep 1 s\n");
2253 //print_cyclic_buffers();
2259 /* max_trace_window_time = current *|/ SCALE + trace_starttime */
2260 sfs_gettime (¤t);
2264 MULTIME (current, PLAY_SCALE);
2267 DIVTIME (current, PLAY_SCALE);
2269 ADDTIME (current, trace_starttime);
2270 max_window_time = current;
2272 /* Right now it is not clear how to deal with the situation where MAX_PLAY_WINDOW is reached */
2273 if (CYCLIC_NUM(dep_window_index) == MAX_PLAY_WINDOW) {
2274 //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);
2276 can_not_catch_speed_num ++;
2278 while ((CYCLIC_NUM(dep_window_index) < MAX_PLAY_WINDOW) &&
2279 (CYCLIC_NUM(dep_window_index) < CYCLIC_NUM(dep_tab_index)) ) {
2281 int dep_index = (dep_window_index.tail+i) % dep_window_index.size;
2282 t.sec = dep_tab[dep_index].timestamp.tv_sec;
2283 t.usec = dep_tab[dep_index].timestamp.tv_usec;
2284 if ((t.sec>max_window_time.sec)||(t.sec==max_window_time.sec && t.usec>max_window_time.usec))
2286 CYCLIC_MOVE_HEAD(dep_window_index);
2289 ADDTIME (current, trace_starttime);
2290 max_window_time = current;
2291 while ((CYCLIC_NUM(dep_window_index) < MAX_PLAY_WINDOW) &&
2292 (CYCLIC_NUM(dep_window_index) < CYCLIC_NUM(dep_tab_index)) ) {
2293 CYCLIC_MOVE_HEAD(dep_window_index);
2298 *poll_timeout_arg = 0;
2299 else if (CYCLIC_NUM(dep_window_index)==CYCLIC_NUM(dep_tab_index)) {
2300 *poll_timeout_arg = 1000; /* poll_timeout set to 1 second for the last request */
2304 struct ladtime tmp1;
2305 tmp.sec = dep_tab[dep_window_index.head].timestamp.tv_sec;
2306 tmp.usec = dep_tab[dep_window_index.head].timestamp.tv_usec;
2307 if (adjust_play_window_debug>=2)
2308 printf ("dep_tab[dep_window_index.head %d].timestamp %d:%d, max_window_time %d:%d\n",
2309 dep_window_index.head, tmp.sec, tmp.usec, max_window_time.sec, max_window_time.usec);
2311 SUBTIME (tmp, max_window_time);
2313 DIVTIME (tmp, PLAY_SCALE);
2316 MULTIME (tmp, PLAY_SCALE);
2321 if (tmp.sec > max_poll_time.sec) {
2324 printf ("dep_tab[%d].timestamp %d:%d, max_window_time %d:%d\n",
2325 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);
2326 printf ("skip %d seconds\n", tmp.sec-max_poll_time.sec);
2327 SUBTIME (tmp, max_poll_time);
2329 skip_sec += tmp.sec;
2330 SUBTIME (test_start, tmp);
2331 tmp = max_poll_time;
2335 //RFS_ASSERT ((tmp.sec < 1000));
2338 if ((tmp.sec ==0) && (tmp.usec==0)) {
2339 *poll_timeout_arg = 0;
2341 *poll_timeout_arg = tmp.sec*1000000+tmp.usec;
2345 struct ladtime tmp1;
2346 tmp.sec = dep_tab[dep_window_max].timestamp.tv_sec;
2347 tmp.usec = dep_tab[dep_window_max].timestamp.tv_usec;
2348 tmp1.sec = dep_tab[dep_window_max-1].timestamp.tv_sec;
2349 tmp1.usec = dep_tab[dep_window_max-1].timestamp.tv_usec;
2350 SUBTIME (tmp, tmp1);
2351 RFS_ASSERT ((tmp.sec < 1000));
2352 RFS_ASSERT ((tmp.sec>0) || ((tmp.sec==0) && (tmp.usec>0)));
2353 *poll_timeout = tmp.sec*1000000+tmp.usec;
2356 *poll_timeout_arg = 100000;
2360 printf ("adjust_play_window: flag %d min %d -> %d, max %d -> %d poll_timeout_arg %d \n",
2361 flag, old_dep_window_index.tail, dep_window_index.tail, old_dep_window_index.head,
2362 dep_window_index.head, *poll_timeout_arg);
2365 printf ("^^^^^^^^^^^^^^^ adjust_play_window, end\n");
2366 CYCLIC_PRINT (dep_tab_index);
2367 printf ("dep_tab[%d].memory_index %d\n", dep_tab_index.tail, dep_tab[dep_tab_index.tail].memory_index);
2368 CYCLIC_PRINT (dep_window_index);
2369 CYCLIC_PRINT (memory_trace_index);
2370 printf (" adjust_play_window, end\n\n");
2375 /* poll for usecs and receive, after receive one reply,
2376 * return index in biod_reqp of the corresponding request
2378 int poll_and_get_reply (int usecs)
2380 int biod_index = -1;
2383 struct timeval zero_time = {0, 0}; /* Immediately return */
2386 //printf("recv thread waitsem 1\n");
2387 waitsem (async_rpc_sem);
2388 //printf("recv thread got sem 1\n");
2391 error = biod_poll_wait (NFS_client, usecs);
2394 if (errno == EINTR) {
2399 (void) fprintf(stderr, "biod_poll_wait error\n");
2401 (void) fflush(stderr);
2408 //printf("recv thread waitsem 2\n");
2409 //waitsem (async_rpc_sem);
2410 //printf("recv thread got sem 2\n");
2411 error = get_areply_udp (NFS_client, &xid, &zero_time);
2412 //postsem (async_rpc_sem);
2413 //printf("recv thread postsem 2\n");
2414 // RFS_ASSERT (error!= RPC_TIMEOUT); /* we have polled and know there is data */
2415 // RFS_ASSERT (error!= RPC_CANTRECV);
2416 RFS_ASSERT (error == RPC_SUCCESS);
2418 biod_index = lookup_biod_req (xid);
2419 sfs_gettime (&(biod_reqp[biod_index].stop));
2426 postsem (async_rpc_sem);
2427 //printf("recv thread postsem 1\n");
2432 void print_result(void)
2438 unsigned long long tmp;
2441 if (DEBUG_CHILD_GENERAL) {
2442 (void) fprintf(stdout, "trace play result:\n");
2443 (void) fprintf(stdout, "\t percentage good_cnt bad_cnt timeout_cnt\telapsed time\t\t\taverage time\n");
2444 for (i=0; i<NOPS+1; i++) {
2445 if (Ops[i].results.good_calls==0) {
2449 tmp = Ops[i].results.time.sec*1000000 + Ops[i].results.time.usec;
2451 avg_usecs = tmp/Ops[i].results.good_calls;
2453 avg_msecs = (Ops[i].results.time.sec*1000 + Ops[i].results.time.usec/1000)/Ops[i].results.good_calls;
2454 avg_usecs = (Ops[i].results.time.usec%1000)/Ops[i].results.good_calls;
2457 (void) fprintf(stdout, "%11s\t%4.1f\t%4d\t%4d\t%4d\t\tsec %8d usec %8d \tusec %8d\n",
2459 (float)(100*Ops[i].results.good_calls)/(float)Ops[TOTAL].results.good_calls,
2460 Ops[i].results.good_calls, Ops[i].results.bad_calls, Ops[i].results.timeout_calls,
2461 Ops[i].results.time.sec, Ops[i].results.time.usec, avg_msecs*1000+avg_usecs);
2463 (void) fflush (stdout);
2466 #if 0 /* commented out by G. Jason Peng */
2467 RFS_ASSERT (read_data_owe_GB==0);
2468 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);
2469 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);
2470 printf("poll_timeout_0_num %d poll_timeout_pos_num %d\n", poll_timeout_0_num, poll_timeout_pos_num);
2471 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",
2472 failed_create_command_num,
2473 failed_other_command_num,
2474 skipped_readlink_command_num,
2475 skipped_custom_command_num,
2476 fh_path_map_err_num,
2477 skipped_fsstat_command_num,
2479 rename_rmdir_noent_reply_num,
2480 rmdir_not_empty_reply_num,
2481 loose_access_control_reply_num,
2482 lookup_err_due_to_rename_num,
2483 lookup_err_due_to_parallel_remove_num,
2484 lookup_eaccess_enoent_mismatch_num,
2486 stale_fhandle_err_num,
2487 abnormal_EEXIST_num,
2488 abnormal_ENOENT_num,
2489 proper_reply_num, run_stage_proper_reply_num);
2492 // print_dump(Client_num, Child_num);
2496 * allocate and initialize client handles
2504 * Set up the client handles. We get them all before trying one
2505 * out to insure that the client handle for LOOKUP class is allocated
2506 * before calling op_getattr().
2508 if (DEBUG_CHILD_GENERAL) {
2509 (void) fprintf(stderr, "%s: set up client handle\n", sfs_Myname);
2512 NFS_client = lad_clnt_create(Tcp? 1: 0, Server_hostent,
2513 (uint32_t) NFS_PROGRAM,
2514 (uint32_t) nfs_version,
2515 RPC_ANYSOCK, &Nfs_timers[0]);
2517 if (NFS_client == ((CLIENT *) NULL)) {
2522 * create credentials using the REAL uid
2524 NFS_client->cl_auth = authunix_create(lad_hostname, (int)Real_uid,
2525 (int)Cur_gid, 0, NULL);
2527 if (biod_init(dummy, dummy) == -1) {
2540 /* Ready to go - initialize operation counters */
2541 for (i = 0; i < NOPS + 1; i++) {
2543 Ops[i].results.good_calls = 0;
2544 Ops[i].results.bad_calls = 0;
2545 Ops[i].results.timeout_calls = 0; // RFS
2546 Ops[i].results.fast_calls = 0;
2547 Ops[i].results.time.sec = 0;
2548 Ops[i].results.time.usec = 0;
2549 Ops[i].results.msec2 = 0;
2552 /* initialize timers and period variables */
2553 sfs_gettime(&Starttime);
2554 Cur_time = Starttime;
2555 start_msec = (Starttime.sec * 1000) + (Starttime.usec / 1000);
2556 Previous_chkpnt_msec = start_msec;
2557 Calls_this_period = 0;
2558 Reqs_this_period = 0;
2559 Sleep_msec_this_period = 0;
2560 Calls_this_test = 0;
2562 Sleep_msec_this_test = 0;
2566 nfs3_strerror(int status)
2568 static char str[40];
2571 (void) strcpy(str, "no error");
2574 (void) strcpy(str, "Not owner");
2577 (void) strcpy(str, "No such file or directory");
2580 (void) strcpy(str, "I/O error");
2583 (void) strcpy(str, "No such device or address");
2586 (void) strcpy(str, "Permission denied");
2589 (void) strcpy(str, "File exists");
2592 (void) strcpy(str, "Cross-device link");
2595 (void) strcpy(str, "No such device");
2597 case NFS3ERR_NOTDIR:
2598 (void) strcpy(str, "Not a directory");
2601 (void) strcpy(str, "Is a directory");
2604 (void) strcpy(str, "Invalid argument");
2607 (void) strcpy(str, "File too large");
2610 (void) strcpy(str, "No space left on device");
2613 (void) strcpy(str, "Read-only file system");
2616 (void) strcpy(str, "Too many links");
2618 case NFS3ERR_NAMETOOLONG:
2619 (void) strcpy(str, "File name too long");
2621 case NFS3ERR_NOTEMPTY:
2622 (void) strcpy(str, "Directory not empty");
2625 (void) strcpy(str, "Disc quota exceeded");
2628 (void) strcpy(str, "Stale NFS file handle");
2630 case NFS3ERR_REMOTE:
2631 (void) strcpy(str, "Object is remote");
2633 case NFS3ERR_BADHANDLE:
2634 (void) strcpy(str, "Bad file handle");
2636 case NFS3ERR_NOT_SYNC:
2637 (void) strcpy(str, "Not sync write");
2639 case NFS3ERR_BAD_COOKIE:
2640 (void) strcpy(str, "Bad cookie");
2642 case NFS3ERR_NOTSUPP:
2643 (void) strcpy(str, "Operation not supported");
2645 case NFS3ERR_TOOSMALL:
2646 (void) strcpy(str, "Value too small");
2648 case NFS3ERR_SERVERFAULT:
2649 (void) strcpy(str, "Server fault");
2651 case NFS3ERR_BADTYPE:
2652 (void) strcpy(str, "Bad type");
2654 case NFS3ERR_JUKEBOX:
2655 (void) strcpy(str, "Jukebox");
2657 case NFS3ERR_RFS_TIMEOUT:
2658 (void) strcpy(str, "Timeout");
2661 (void) sprintf(str, "Unknown status %d", status);
2668 * Check the gettimeofday() resolution. If the resolution
2669 * is in chunks bigger than SFS_MIN_RES then the client
2670 * does not have a usable resolution for running the
2677 char tmp_hostname[HOSTNAME_LEN];
2679 time_res = get_resolution();
2680 getmyhostname(tmp_hostname, HOSTNAME_LEN);
2681 if( time_res > (double)SFS_MIN_RES )
2683 (void) fprintf(stderr,
2684 "\n%s: Clock resolution too poor to obtain valid results.\n",
2686 (void) fprintf(stderr,
2687 "%s: Clock resolution %f Micro seconds.\n", tmp_hostname,
2693 (void) fprintf(stderr,
2694 "\n%s: Good clock resolution [ %f ] Micro seconds.\n",
2695 tmp_hostname, time_res);
2700 * Lifted code from Iozone with permission from author. (Don Capps)
2701 * Returns the resolution of the gettimeofday() function
2705 get_resolution(void)
2707 double starttime, finishtime, besttime;
2711 finishtime=time_so_far1(); /* Warm up the instruction cache */
2712 starttime=time_so_far1(); /* Warm up the instruction cache */
2713 delay=j=0; /* Warm up the data cache */
2718 starttime=time_so_far1();
2719 for(j=0;j< delay;j++)
2721 finishtime=time_so_far1();
2722 if(starttime==finishtime)
2727 besttime=(finishtime-starttime);
2728 if((finishtime-starttime) < besttime)
2729 besttime=(finishtime-starttime);
2738 * Lifted code from Iozone with permission from author. (Don Capps)
2739 * Returns current result of gettimeofday() in microseconds.
2741 /************************************************************************/
2742 /* Time measurement routines. */
2743 /* Return time in microseconds */
2744 /************************************************************************/
2749 /* For Windows the time_of_day() is useless. It increments in 55 */
2750 /* milli second increments. By using the Win32api one can get */
2751 /* access to the high performance measurement interfaces. */
2752 /* With this one can get back into the 8 to 9 microsecond */
2755 LARGE_INTEGER freq,counter;
2759 QueryPerformanceFrequency(&freq);
2760 QueryPerformanceCounter(&counter);
2761 bigcounter=(double)counter.HighPart *(double)0xffffffff +
2762 (double)counter.LowPart;
2763 wintime = (double)(bigcounter/(double)freq.LowPart);
2764 return((double)wintime*1000000.0);
2766 #if defined (OSFV4) || defined(OSFV3) || defined(OSFV5)
2769 if (getclock(TIMEOFDAY, (struct timespec *) &gp) == -1)
2771 return (( (double) (gp.tv_sec)*1000000.0) +
2772 ( ((float)(gp.tv_nsec)) * 0.001 ));
2776 if (gettimeofday(&tp, (struct timezone *) NULL) == -1)
2777 perror("gettimeofday");
2778 return ((double) (tp.tv_sec)*1000000.0) +
2779 (((double) tp.tv_usec) );
2787 fprintf(stderr, "trace play usage");
2789 extern void init_file_system (void)
2794 void show_fhandle (nfs_fh3 * fhp)
2796 struct knfs_fh * kfhp = (struct knfs_fh *)fhp;
2803 RFS_ASSERT (kfhp->fh_version == 1);
2804 RFS_ASSERT (kfhp->fh_fsid_type == 0);
2805 RFS_ASSERT (kfhp->fh_auth_type == 0);
2807 dev = ntohs(kfhp->fh_dev_major);
2809 dev = dev + ntohs(kfhp->fh_dev_minor);
2811 /* kfhp->fh_dev_ino hold the inode number of export point of the mounted
2812 * file system. For example, if /tmp/t1 is exported, /tmp/t1/t2 is mounted,
2813 * then fh_dev_ino hold the inode number of t1, not t2
2816 switch (kfhp->fh_fileid_type) {
2818 printf("fh:type 0 root dev 0x%x dev_ino %d\n", dev, kfhp->fh_dev_ino);
2821 printf("fh:type 1 %d %x dev %x dev_ino %x\n",
2822 kfhp->fh_ino, kfhp->fh_generation, dev, kfhp->fh_dev_ino);
2825 printf("fh:type2 %d %x dirino %d dev 0x%x dev_ino %x\n",
2826 kfhp->fh_ino, kfhp->fh_generation, kfhp->fh_dirino, dev, kfhp->fh_dev_ino);
2833 nfs_fh3 zero_fhandle;
2836 memset (fh_map, 0, sizeof (fh_map));
2837 memset(fh_htable, 0, sizeof (fh_htable));
2838 memset (&zero_fhandle, 0, sizeof(nfs_fh3));
2839 printf ("SIZE of fh map %d KB\n", sizeof (fh_map)/1000);
2843 int add_fh (int map_flag, char * trace_fh, char * path, nfs_fh3 * play_fh)
2845 char * old_trace_fh;
2847 /* first lookup if the entry for fh is already in the table */
2848 struct generic_entry * p;
2850 p = generic_lookup (trace_fh, TRACE_FH_SIZE, 0, fh_htable, FH_HTABLE_SIZE);
2852 RFS_ASSERT (fh_map[p->key3].flag = FH_MAP_FLAG_PARTIAL);
2853 RFS_ASSERT (map_flag ==FH_MAP_FLAG_COMPLETE);
2854 fh_map[p->key3].flag = map_flag;
2855 //RFS_ASSERT (!memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE));
2856 if (memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE)) {
2858 printf ("fh_map[%d].trace_fh %s trace_fh %s", p->key3, fh_map[p->key3].trace_fh, trace_fh);
2859 for (i=0; i<fh_i; i++) {
2860 int * p1 = (int *)&(fh_map[i].play_fh);
2861 #ifdef COMPRESS_TRACE_FH
2862 int * p = (int *)fh_map[i].trace_fh;
2863 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",
2864 i, *p, *(p+1), *(p+2), *(p+3), *(p+4), *(p+5), *(p+6), *(p+7), fh_map[i].path,
2865 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
2867 printf("fh_map[%d].trace_fh %s path %s \nnew_filehandle %8x%8x%8x%8x%8x%8x%8x%8x\n",
2868 i, fh_map[i].trace_fh, fh_map[i].path,
2869 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
2874 RFS_ASSERT (!strcmp(fh_map[p->key3].path, path));
2875 /* It's possible that in fh-path-map, many trace_fh are corresponding to one path
2876 * some of it may be the result of lookup after symlink, which is not handled
2877 * properly as new created objects
2879 #ifdef TAKE_CARE_SYMBOLIC_LINK
2880 RFS_ASSERT (!memcmp(&fh_map[p->key3].play_fh, &zero_fhandle, sizeof(nfs_fh3)));
2882 memcpy (&fh_map[p->key3].play_fh, play_fh, sizeof (nfs_fh3));
2883 if ((fh_map_debug==1)) // || (stage ==TRACE_PLAY_STAGE))
2884 printf ("update the play_fh for trace_fh %s path %s \n", trace_fh, path);
2888 fh_map[fh_i].flag = map_flag;
2889 fh_map[fh_i].lock = 0;
2890 strncpy(fh_map[fh_i].trace_fh, trace_fh, TRACE_FH_SIZE);
2892 RFS_ASSERT (strlen(path) < MAX_PLAY_PATH_SIZE);
2893 strcpy (fh_map [fh_i].path, path);
2894 if (map_flag==FH_MAP_FLAG_COMPLETE)
2895 memcpy (&fh_map[fh_i].play_fh, play_fh, sizeof(nfs_fh3));
2897 memset (&fh_map[fh_i].play_fh, 0, sizeof(nfs_fh3));
2899 if ((fh_map_debug==1)) { // || (stage ==TRACE_PLAY_STAGE)) {
2900 printf ("insert trace_fh %s path %s play_fh:\n", trace_fh, path);
2901 if (map_flag == FH_MAP_FLAG_COMPLETE) {
2902 //show_fhandle(play_fh);
2908 if (map_flag == FH_MAP_FLAG_DISCARD)
2909 printf ("insert flag %d trace_fh %s path %s play_fh:\n", map_flag, trace_fh, path);
2912 generic_insert(trace_fh, TRACE_FH_SIZE, fh_i, fh_htable, FH_HTABLE_SIZE);
2915 RFS_ASSERT (fh_i < FH_MAP_SIZE);
2920 inline fh_map_t * lookup_fh (char * trace_fh )
2922 struct generic_entry * p;
2923 p = generic_lookup (trace_fh, TRACE_FH_SIZE, 0, fh_htable, FH_HTABLE_SIZE);
2924 if (fh_map_debug==1)
2925 printf ("lookup trace_fh %s\n", trace_fh);
2928 if (fh_map_debug==1) {
2929 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);
2930 //show_fhandle(&fh_map[p->key3].play_fh);
2932 RFS_ASSERT (!memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE));
2933 return (&(fh_map[p->key3]));
2935 //printf ("lookup_fh %s not found\n", trace_fh);
2936 if (stage != READ_DEP_TAB_STAGE && (fh_map_debug==1)) {
2937 printf ("lookup not found trace_fh %s\n", trace_fh);
2944 int delete_fh (char * trace_fh, int fh_map_index)
2946 generic_delete (trace_fh, TRACE_FH_SIZE, fh_map_index, fh_htable, FH_HTABLE_SIZE);
2950 int lookup_init_filesystem (nfs_fh3 * parent, char * name, nfs_fh3 * result)
2953 LOOKUP3res reply; /* the reply */
2954 enum clnt_stat rpc_stat; /* result from RPC call */
2955 struct ladtime start;
2956 struct ladtime stop;
2959 /* set up the arguments */
2960 (void) memcpy((char *) &args.what.dir, (char *) parent,
2962 args.what.name = name;
2963 (void) memset((char *) &reply.resok.object, '\0', sizeof (nfs_fh3));
2966 sfs_gettime(&start);
2967 rpc_stat = clnt_call(NFS_client, NFSPROC3_LOOKUP,
2968 xdr_LOOKUP3args, (char *) &args,
2969 xdr_LOOKUP3res, (char *) &reply,
2973 if (rpc_stat !=RPC_SUCCESS) {
2974 printf("rpc_stat %d\n", rpc_stat);
2977 RFS_ASSERT (rpc_stat == RPC_SUCCESS);
2978 (void) memcpy((char *) result, (char *) &reply.resok.object, sizeof (nfs_fh3));
2979 return (reply.status);
2982 void read_fh_map(char * fh_map_file)
2987 char trace_fh[MAX_TRACE_FH_SIZE];
2992 #define MAX_PATH_DEPTH 20
2993 nfs_fh3 parents[MAX_PATH_DEPTH];
2994 char * lookup_path_ptr[MAX_PATH_DEPTH];
2995 char lookup_path [MAX_PLAY_PATH_SIZE];
2997 int new_dir_flag = 0;
3001 memset(lookup_path_ptr, 0, sizeof(lookup_path_ptr));
3002 memcpy(&parents[depth], &(Export_dir.fh_data->sfs_fh_un.f_fh3), sizeof(nfs_fh3));
3003 strcpy(lookup_path, "/");
3004 lookup_path_ptr[depth]=&lookup_path[0];
3006 fp = fopen(fh_map_file, "r");
3008 printf ("can not opern %s\n", fh_map_file);
3012 RFS_ASSERT (fp!=NULL);
3013 if (strstr(fh_map_file, "fmt1")) {
3019 memset(buf, 0, sizeof(buf));
3020 while (fgets(buf, 1024, fp)) {
3022 if (fh_i % 10000==0)
3023 printf("%d fh_map entry read\n", fh_i);
3025 RFS_ASSERT (buf[strlen(buf)-1]=='\n');
3026 buf[strlen(buf)-1]=0;
3028 printf("%d fgets return %s\n", fh_i, buf);
3029 printf("depth %d lookup_path %s\n", depth, lookup_path);
3031 //for (i=0; i<=depth; i++)
3032 //printf("lookup_path_ptr[%d] %s ", i, lookup_path_ptr[i]);
3034 #ifdef COMPRESS_TRACE_FH
3035 for (i=0; i<TRACE_FH_SIZE/8; i++) {
3036 strncpy(intbuf, buf+i*8, 8);
3037 sscanf(intbuf, "%x", trace_fh+i*8); // maybe it should be 4, anyway we don't compress for now
3039 trace_path = buf+TRACE_FH_SIZE*2+1; /* +1 the trace contains only initial file handle */
3041 memcpy(trace_fh, buf, TRACE_FH_SIZE);
3042 trace_path = buf + TRACE_FH_SIZE +1;
3044 #ifdef TRACE_CONTAIN_LATER_FHANDLE
3045 trace_path = +=2; /* +3 if the trace contains both initial and later created file handle */
3048 #ifdef NO_DEPENDENCY_TABLE
3049 if (!strncmp (trace_path, "DISCARD", 7) ||
3050 !strncmp (trace_path, "LN", 2) ) {
3051 map_flag = FH_MAP_FLAG_DISCARD;
3052 add_fh (map_flag, buf, trace_path, 0);
3057 p = trace_path+strlen(trace_path)-2;
3061 //RFS_ASSERT (p-trace_path<=strlen(lookup_path)+1);
3062 //RFS_ASSERT (p>trace_path);
3064 if (strncmp(lookup_path, trace_path, p-trace_path)) {
3065 printf("strncmp lookup_path %s trace_path %s for length %d\n", lookup_path, trace_path, p-trace_path);
3067 RFS_ASSERT (!strncmp(lookup_path, trace_path, p-trace_path));
3068 //while (strncmp(lookup_path, trace_path, p-trace_path)) { /* one step deeper */
3069 while (strlen(lookup_path)>p-trace_path && depth>0) {
3070 //printf("depth--\n");
3072 printf ("lookup_path %s trace_path %s p-trace_path %d depth %d\n", lookup_path, trace_path, p-trace_path, depth);
3073 RFS_ASSERT (depth>0);
3074 *lookup_path_ptr[depth]=0;
3075 lookup_path_ptr[depth]=0;
3078 RFS_ASSERT (strlen(lookup_path)==(p-trace_path) || (depth==0));
3081 #ifdef TRACE_CONTAIN_LATER_FHANDLE
3082 if (buf[TRACE_FH_SIZE*2+1]=='Y') {
3083 map_flag = FH_MAP_FLAG_COMPLETE;
3085 map_flag = FH_MAP_FLAG_PARTIAL;
3086 RFS_ASSERT (buf[TRACE_FH_SIZE*2+1]=='N');
3089 map_flag = FH_MAP_FLAG_COMPLETE;
3091 if ((*(p+strlen(p)-1))=='/') {
3097 if (map_flag == FH_MAP_FLAG_COMPLETE) {
3098 int ret = lookup_init_filesystem (&parents[depth], p, &parents[depth+1]);
3100 printf ("lineno %d %s\n", lineno, buf);
3102 RFS_ASSERT (ret == NFS3_OK);
3103 add_fh (map_flag, buf, trace_path, &parents[depth+1]);
3105 add_fh (map_flag, buf, trace_path, 0);
3108 /* the new fhandle is of a directory */
3109 lookup_path_ptr[depth+1] = lookup_path+strlen(lookup_path);
3110 strcat (lookup_path, p);
3111 strcat (lookup_path, "/");
3113 //printf("depth++\n");
3117 memset(buf, 0, sizeof(buf));
3121 for (i=0; i<fh_i; i++) {
3122 int * p1 = (int *)&(fh_map[i].play_fh);
3123 #ifdef COMPRESS_TRACE_FH
3124 int * p = (int *)fh_map[i].trace_fh;
3125 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",
3126 i, *p, *(p+1), *(p+2), *(p+3), *(p+4), *(p+5), *(p+6), *(p+7), fh_map[i].path,
3127 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
3129 printf("fh_map[%d].trace_fh %s path %s \nnew_filehandle %8x%8x%8x%8x%8x%8x%8x%8x\n",
3130 i, fh_map[i].trace_fh, fh_map[i].path,
3131 *p1, *(p1+1), *(p1+2), *(p1+3), *(p1+4), *(p1+5), *(p1+6), *(p1+7));
3135 fprintf(stderr, "total %d requests \n", i);
3144 inline free_biod_req (int biod_index)
3146 RFS_ASSERT (biod_reqp[biod_index].in_use == TRUE);
3147 biod_reqp[biod_index].in_use = FALSE;
3151 void finish_request (int biod_index, int dep_index, int status, int dep_flag)
3154 /* the ending operation, same as when a request time out */
3156 dep_tab[dep_index].stop = biod_reqp[biod_index].stop; /* RFS: to dump data */
3157 free_biod_req (biod_index);
3159 dep_tab[dep_index].status = status;
3161 if (event_order_index < EVENT_ORDER_SIZE)
3162 event_order[event_order_index++] = -dep_tab[dep_index].disk_index;
3164 dep_tab[dep_index].flag = dep_flag;
3165 if (is_dir_op(dep_tab[dep_index].proc)) {
3167 RFS_ASSERT (dep_tab[dep_index].fh->lock = 1);
3168 dep_tab[dep_index].fh->lock = 0;
3169 if (dep_tab[dep_index].proc==RENAME)
3170 dep_tab[dep_index].fh_2->lock = 0;
3171 j = dep_tab[dep_index].fh-fh_map;
3172 if (dependency_debug) {
3173 printf ("fh_map[%d] is UNlocked\n",j);
3174 printf ("trace_fh %d path %s\n", dep_tab[dep_index].fh->trace_fh, dep_tab[dep_index].fh->path);
3175 printf ("trace_fh %d path %s\n", fh_map[j].trace_fh, fh_map[j].path);
3180 /* the request argument may have pointers pointing to buffers, e.g. the name in lookup,
3181 * the target of symlink, the write data */
3182 char arg_res[MAX_ARG_RES_SIZE];
3183 char buf1 [MAX_BUF1_SIZE];
3184 char buf2 [MAX_BUF2_SIZE];
3186 int execute_next_request ()
3191 struct biod_req * reqp;
3192 sfs_op_type *op_ptr; /* per operation info */
3193 struct ladtime call_timeout;
3194 static int last_print_time = -1;
3196 if (num_out_reqs == max_biod_reqs) {
3200 start_profile (&valid_get_nextop_profile);
3201 start_profile (&invalid_get_nextop_profile);
3202 dep_index = get_nextop();
3203 if (dep_index == -1) {
3204 end_profile (&invalid_get_nextop_profile);
3207 end_profile (&valid_get_nextop_profile);
3209 start_profile (&prepare_argument_profile);
3210 line = dep_tab[dep_index].line;
3212 if (per_packet_debug)
3213 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);
3215 end_profile(&total_profile);
3216 if ((total_profile.in.tv_sec - last_print_time >= 10)) {
3217 last_print_time = total_profile.in.tv_sec;
3218 //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);
3220 CYCLIC_PRINT (dep_tab_index);
3222 int tmp = CYCLIC_MINUS(dep_tab_index.head,1,dep_tab_index.size);
3223 printf("dep_tab_index.head-1 %d disk_index %d tail %d disk_index %d\n", tmp, dep_tab[tmp].disk_index,
3224 dep_tab_index.tail, dep_tab[dep_tab_index.tail].disk_index);
3230 if (can_not_catch_speed_num < 2000) {
3232 printf ("set PLAY_SCALE to %d\n", PLAY_SCALE);
3234 if (can_not_catch_speed_num > 50000) {
3237 if (can_not_catch_speed_num > 5000) {
3245 if ((total_profile.in.tv_sec > 100)) {
3246 can_not_catch_speed_num_total += can_not_catch_speed_num;
3248 can_not_catch_speed_num = 0;
3252 printf ("processing dep_tab[%d] disk_index %d %s\n", dep_index, dep_tab[dep_index].disk_index, line);
3254 proc = dep_tab[dep_index].proc;
3255 rfs_Ops[proc].setarg (dep_index, line, arg_res, buf1, buf2);
3257 op_ptr = &Ops[proc];
3258 reqp = get_biod_req (dep_index);
3261 #ifdef notdef /* place to set request timeout. G. Jason Peng */
3262 call_timeout.sec = 2; //Nfs_timers[op_ptr->call_class].tv_sec;
3263 call_timeout.usec = Nfs_timers[op_ptr->call_class].tv_usec;
3265 call_timeout.sec = 0;
3266 call_timeout.usec = 300000;
3267 //call_timeout.usec = 14000;
3268 //call_timeout.usec = 13000;
3269 //call_timeout.usec = 6000;
3270 //call_timeout.usec = 8000;
3271 //call_timeout.usec = 10000;
3275 sfs_gettime(&(reqp->start));
3276 end_profile (&prepare_argument_profile);
3277 start_profile (&biod_clnt_call_profile);
3282 //printf ("send thread waitsem\n");
3283 waitsem(async_rpc_sem);
3284 //printf ("send thread got sem\n");
3286 reqp->xid = biod_clnt_call(NFS_client, rfs_Ops[proc].nfsv3_proc,
3287 rfs_Ops[proc].xdr_arg, arg_res);
3289 postsem(async_rpc_sem);
3290 //printf ("send thread postsem\n");
3294 reqp->xid = dep_index+1; /* just fake a message id and let it expire */
3296 RFS_ASSERT (reqp->xid != 0);
3297 reqp->timeout = reqp->start;
3298 ADDTIME (reqp->timeout, call_timeout);
3299 dep_tab[dep_index].flag = DEP_FLAG_SENT;
3300 if (event_order_index < EVENT_ORDER_SIZE)
3301 event_order[event_order_index++] = dep_tab[dep_index].disk_index;
3303 dep_tab[dep_index].start = reqp->start; /* RFS: to dump data */
3304 end_profile (&biod_clnt_call_profile);
3309 void check_reply (int proc, int biod_index, int dep_index, int status, char * errmsg, int trace_status)
3311 if (((status!=trace_status)) && (status!=NFS3_OK) && (trace_status!=NFS3ERR_RFS_MISS)) {
3313 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);
3314 #ifndef TAKE_CARE_UNLOOKED_UP_NON_NEW_FILES
3315 /* these files is not looked up and is not create/mkdir/symlink/link/mknod ed before they
3316 * are refered by name through rename, remove
3318 if ((proc==RENAME || proc==REMOVE) && (status==NFS3ERR_NOENT) && (trace_status ==0)) {
3319 /* current initialization doesnot take care of rename source, if there is no
3320 * create or lookup before that source, the source object will not exist when
3323 rename_rmdir_noent_reply_num++;
3326 #ifndef TAKE_CARE_SYMBOLIC_LINK
3327 if ((proc==LOOKUP) && (status==NFS3_OK) && (trace_status==NFS3ERR_NOENT)) {
3328 /* in the original trace, first lookup return NOENT, then symlink is executed, then lookup return OK
3329 * the initialization considers only the lookup return OK and created the file in the initialization
3330 * so in trace play the first lookup return OK
3333 } else // if ((proc==SYMLINK) && (status == NFS3ERR_EXIST) && (trace_status == 0)) {
3334 /* trace_status could be EAGAIN */
3335 if ((proc==SYMLINK) && (status == NFS3ERR_EXIST) ) {
3336 /* due to similar reason as above, the initialization code initializes the symbolic link as a normal
3342 #ifndef TAKE_CARE_NOEMPTY_RMDIR
3343 /* the remove packet seems got lost in the trace capture, so replay can not finish */
3344 if ((proc==RMDIR) && (status==NFS3ERR_NOTEMPTY)) {
3346 RENAME3res reply; /* the reply */
3347 RMDIR3args * rmdir_argp;
3348 enum clnt_stat rpc_stat; /* result from RPC call */
3350 rfs_Ops[proc].setarg (dep_index, dep_tab[dep_index].line, arg_res, buf1, buf2);
3351 rmdir_argp = (RMDIR3args *)arg_res;
3353 memcpy(&args.from, &(rmdir_argp->object), sizeof (diropargs3));
3354 memcpy(&args.to.dir, &(Export_dir.fh_data->sfs_fh_un.f_fh3), sizeof(nfs_fh3));
3355 args.from.name = buf1; /* the buf1 is already filled when parsing rmdir */
3356 args.to.name = buf2;
3357 sprintf(buf2, "rmdir_%d_%s", dep_tab[dep_index].disk_index, rmdir_argp->object.name);
3359 rpc_stat = clnt_call(NFS_client, NFSPROC3_RENAME,
3360 xdr_RENAME3args, (char *) &args,
3361 xdr_RENAME3res, (char *) &reply,
3363 RFS_ASSERT (rpc_stat == RPC_SUCCESS);
3364 if (reply.status!=NFS3_OK)
3365 printf ("change rmdir into rename, reply.status %d\n", reply.status);
3366 RFS_ASSERT (reply.status==NFS3_OK);
3367 rmdir_not_empty_reply_num ++;
3369 #ifndef TAKE_CARE_ACCESS_ERROR
3370 } else if ((status==0) && (trace_status==NFS3ERR_ACCES)) {
3371 loose_access_control_reply_num ++;
3373 #ifdef NO_DEPENDENCY_TABLE
3374 } else if ((proc==LOOKUP) && (status==NFS3ERR_NOENT) && (trace_status==NFS3_OK)) {
3375 lookup_err_due_to_rename_num ++;
3376 } else if ((proc==LOOKUP) && (status==NFS3_OK) && (trace_status == NFS3ERR_NOENT)) {
3377 /* if there is a remove in front of the lookup, but it is
3378 * actually executed later than the lookup
3380 lookup_err_due_to_parallel_remove_num ++;
3382 #ifndef TAKE_CARE_LOOKUP_EACCESS_ENOENT_MISMATCH
3383 /* if the looked return EACCESS in the trace, means the object still exists
3384 * should have initialized, right not don't initialize it, hence play status
3387 } else if ((proc==LOOKUP) && (status==NFS3ERR_NOENT) && (trace_status==NFS3ERR_ACCES)) {
3388 lookup_eaccess_enoent_mismatch_num ++;
3390 #ifdef TOLERANT_READ_IO_ERR
3391 } else if ((proc==READ) && (status==NFS3ERR_IO) && (trace_status==NFS3_OK)) {
3394 #ifdef TOLERANT_STALE_FHANDLE_ERR
3395 } else if ((status==NFS3ERR_STALE) && (trace_status==NFS3_OK)) {
3396 printf ("!!!!!!! STALE FILE HANDLE \n");
3398 stale_fhandle_err_num ++;
3402 for (i=dep_window_index.tail; CYCLIC_LESS(dep_window_index,i,dep_window_index.head); i++) {
3403 if (dep_tab[i].flag!=1)
3404 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);
3407 if (status==EEXIST) {
3408 abnormal_EEXIST_num ++;
3409 } else if (status == ENOENT) {
3410 abnormal_ENOENT_num ++;
3412 printf ("!!!!!!!!!!!!!1 should fail\n");
3417 proper_reply_num ++;
3418 if (total_profile.in.tv_sec >= WARMUP_TIME)
3419 run_stage_proper_reply_num ++;
3424 /* return -1 if there is no reply being received
3425 * return the dep_index if the corresponding reply has been received
3427 int receive_next_reply (int busy_flag)
3434 sfs_op_type *op_ptr; /* per operation info */
3439 int poll_timeout = 0; /* timeout in usecs */
3441 /* wait for reply */
3442 start_profile (&valid_poll_and_get_reply_profile);
3443 start_profile (&invalid_poll_and_get_reply_profile);
3445 if (busy_flag == BUSY) {
3447 poll_timeout_0_num ++;
3449 poll_timeout = 2000; /* 10000 or 2000 is a better number in non-debugging state */
3450 //poll_timeout = 0; /* 10000 or 2000 is a better number in non-debugging state */
3451 poll_timeout_pos_num ++;
3454 biod_index = poll_and_get_reply (poll_timeout);
3455 if (biod_index==-1) {
3456 end_profile (&invalid_poll_and_get_reply_profile);
3459 end_profile (&valid_poll_and_get_reply_profile);
3461 start_profile (&decode_reply_profile);
3462 /* check the corresponding request */
3463 dep_index = biod_reqp[biod_index].dep_tab_index;
3464 if (biod_reqp[biod_index].in_use==1) {
3465 RFS_ASSERT (dep_tab[dep_index].biod_req_index == biod_index);
3467 printf ("biod_index %d reply received but the request has been time out\n", biod_index);
3471 proc = dep_tab[dep_index].proc;
3472 op_ptr = &Ops[proc];
3474 if (dep_tab[dep_index].flag != DEP_FLAG_SENT) {
3475 printf("dep_tab[%d].flag %d proc %d status %d start %d:%d stop %d:%d\n",
3476 dep_index, dep_tab[dep_index].flag, proc, dep_tab[dep_index].status,
3477 dep_tab[dep_index].start.sec, dep_tab[dep_index].start.usec,
3478 dep_tab[dep_index].stop.sec, dep_tab[dep_index].stop.usec );
3479 printf ("received reply for timeout requests dep_tab[%d].disk_index %d\n", dep_index, dep_tab[dep_index].disk_index);
3482 RFS_ASSERT (dep_tab[dep_index].flag == DEP_FLAG_SENT);
3484 /* decode the reply */
3485 rfs_Ops[proc].setres (arg_res, buf1);
3486 ret = proc_header (NFS_client, rfs_Ops[proc].xdr_res, arg_res);
3487 RFS_ASSERT (ret == RPC_SUCCESS);
3488 status = *((int *)arg_res);
3489 errmsg = nfs3_strerror (status);
3490 end_profile (&decode_reply_profile);
3492 start_profile (&check_reply_profile);
3493 /* compare with the reply in the trace */
3494 line = dep_tab[dep_index].line;
3495 reply_line = dep_tab[dep_index].reply_line;
3496 trace_status = dep_tab[dep_index].trace_status;
3498 if (per_packet_debug || rfs_debug )
3499 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);
3501 /* error checking */
3502 check_reply (proc, biod_index, dep_index, status, errmsg, trace_status);
3504 /* free resources */
3505 finish_request (biod_index, dep_index, status, DEP_FLAG_DONE);
3508 /* we set 100 seconds warm up time */
3509 if ((total_profile.in.tv_sec >= WARMUP_TIME)) {
3510 /* get statistics */
3511 if (status == trace_status || (status==NFS3_OK && trace_status==NFS3ERR_RFS_MISS) ) {
3512 op_ptr->results.good_calls++;
3513 Ops[TOTAL].results.good_calls++;
3515 op_ptr->results.bad_calls++;
3516 Ops[TOTAL].results.bad_calls++;
3518 sfs_elapsedtime (op_ptr, &(biod_reqp[biod_index].start), &(biod_reqp[biod_index].stop));
3519 end_profile (&check_reply_profile);
3522 //start_profile (&add_create_object_profile);
3524 if (trace_status == NFS3_OK && (proc==CREATE || proc==MKDIR || proc==SYMLINK || proc==MKNOD)) {
3525 #ifndef REDUCE_MEMORY_TRACE_SIZE
3526 RFS_ASSERT (reply_line);
3528 if (status!=NFS3_OK) {
3529 /* commented out for 1022 */
3530 printf ("!!!!!! Should have been an ASSERTION FAILURE \n");
3531 RFS_ASSERT (proc==SYMLINK);
3534 if (proc!=SYMLINK || line[TRACE_VERSION_POS]!='2')
3535 add_new_file_system_object(proc, dep_index, line, reply_line);
3538 //end_profile (&add_create_object_profile);
3541 inline void add_new_file_system_object (int proc, int dep_index, char * line, char * reply_line)
3543 char * child_trace_fh;
3544 fh_map_t * parent_entryp;
3545 char component_name[MAX_PLAY_PATH_SIZE];
3546 char * parent_trace_fh;
3547 char child_path[MAX_PLAY_PATH_SIZE];
3548 post_op_fh3 * post_op_fh3_child;
3549 char * reply_trace_fh;
3550 nfs_fh3 * child_fh3;
3552 parent_trace_fh = strstr (line, "fh");
3553 RFS_ASSERT (parent_trace_fh);
3554 parent_trace_fh +=3;
3555 parent_entryp = lookup_fh (parent_trace_fh);
3556 RFS_ASSERT (parent_entryp);
3557 parse_name (parent_trace_fh+65, component_name);
3558 strcpy (child_path, parent_entryp->path);
3559 strcat (child_path, "/");
3560 strcat (child_path, component_name);
3562 /* find the corresponding create request */
3563 //printf ("before find reply trace_fh reply_line %s\n", reply_line);
3564 #ifdef REDUCE_MEMORY_TRACE_SIZE
3565 reply_trace_fh = dep_tab[dep_index].reply_trace_fh;
3567 reply_trace_fh = find_reply_trace_fh (reply_line);
3569 RFS_ASSERT (reply_trace_fh != NULL);
3572 RFS_ASSERT (((CREATE3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3573 child_fh3 = &((CREATE3res *)arg_res)->res_u.ok.obj.handle;
3576 RFS_ASSERT (((MKDIR3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3577 child_fh3 = &((MKDIR3res *)arg_res)->res_u.ok.obj.handle;
3580 RFS_ASSERT (((SYMLINK3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3581 child_fh3 = &((SYMLINK3res *)arg_res)->res_u.ok.obj.handle;
3584 RFS_ASSERT (((MKNOD3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3585 child_fh3 = &((MKNOD3res *)arg_res)->res_u.ok.obj.handle;
3588 RFS_ASSERT (proc==LOOKUP);
3589 child_fh3 = &((LOOKUP3res *)arg_res)->res_u.ok.object;
3594 #ifndef REDUCE_MEMORY_TRACE_SIZE
3595 RFS_ASSERT (reply_trace_fh[TRACE_FH_SIZE]==' ');
3597 reply_trace_fh[TRACE_FH_SIZE] = 0;
3598 add_fh (FH_MAP_FLAG_COMPLETE, reply_trace_fh, child_path, child_fh3); /* exist flag is not used now, set to 1 */
3599 #ifndef REDUCE_MEMORY_TRACE_SIZE
3600 /* just to preserve the original reply line not changed */
3601 reply_trace_fh[TRACE_FH_SIZE] = ' ';
3605 /* initialize timestamp and proc field of dep_tab entry */
3606 void trace_play(void)
3609 /* The flag to indicate whether trace_player is BUSY. Trace_player is BUSY
3610 * when either there is request to send or there is reply being
3611 * received. Otherwise it is IDLE. The timeout for polling replies
3612 * is set to 0 when BUSY, it is set to the waiting time to the first
3613 * request outside of current <min_dep_index, dep_window_max> window when IDLE.
3615 int busy_flag = BUSY;
3616 //int dep_index; /* index into dependency table: dep_tab */
3617 //int biod_index; /* index into outstanding requests: biod_reqp */
3618 static int last_print_time = -1;
3619 int poll_timeout = 0;
3622 disk_io_status = read_trace();
3625 RFS_ASSERT (!CYCLIC_EMPTY(dep_tab_index));
3626 CYCLIC_MOVE_HEAD(dep_window_index);
3628 adjust_play_window(busy_flag, &poll_timeout);
3630 start_profile (&total_profile);
3631 while (!CYCLIC_EMPTY(dep_tab_index)) {
3632 end_profile(&total_profile);
3633 if ((total_profile.in.tv_sec - last_print_time >= 10)) {
3636 last_print_time = total_profile.in.tv_sec;
3637 fprintf (stdout, ">>>> sendng thread: time %d send_num %d recv_num %d timeout_num %d num_out_reqs %d can_not_catch_speed_num %d PLAY_SCALE %d \n", total_profile.in.tv_sec, send_num, recv_num, timeout_num, num_out_reqs, can_not_catch_speed_num, PLAY_SCALE);
3638 for (i=0; i<=MAX_OUTSTANDING_REQ; i++) {
3639 if (num_out_reqs_statistics[i]!=0) {
3640 printf("num_out_req[%d]=%d,", i, num_out_reqs_statistics[i]);
3641 num_out_reqs_statistics[i]=0;
3645 for (i=0; i<=MAX_OUTSTANDING_REQ; i++) {
3646 if (num_out_reqs_statistics_at_timeout[i]!=0) {
3647 printf("num_out_req_at_timeout[%d]=%d,", i, num_out_reqs_statistics_at_timeout[i]);
3648 num_out_reqs_statistics_at_timeout[i]=0;
3652 // CYCLIC_PRINT(dep_tab_index);
3655 if ((total_profile.in.tv_sec > 6000)) {
3656 printf ("the process has run for more than 600 seconds, exit\n");
3660 if (busy_flag == IDLE) {
3662 //start_profile (&check_timeout_profile);
3664 //end_profile (&check_timeout_profile);
3667 if (disk_io_status!=TRACE_FILE_END) {
3668 disk_io_status = read_trace();
3673 //start_profile (&adjust_play_window_profile);
3674 adjust_play_window (busy_flag, &poll_timeout);
3676 printf("num_out_reqs %d\n", num_out_reqs);
3677 num_out_reqs_statistics[num_out_reqs]++;
3679 //end_profile (&adjust_play_window_profile);
3681 start_profile (&execute_next_request_profile);
3682 while (execute_next_request()!=-1) {
3685 end_profile (&execute_next_request_profile);
3688 start_profile (&receive_next_reply_profile);
3689 /* actually the performance of two policy seems to be same */
3690 //#define SEND_HIGHER_PRIORITY_POLICY
3691 #define SEND_RECEIVE_EQUAL_PRIORITY_POLICY
3693 #ifdef SEND_HIGHER_PRIORITY_POLICY
3694 receive_next_reply(IDLE);
3696 #ifdef SEND_RECEIVE_EQUAL_PRIORITY_POLICY
3698 while (receive_next_reply(busy_flag)!=-1)
3701 end_profile (&receive_next_reply_profile);
3705 end_profile (&total_profile);
3707 RFS_ASSERT (disk_io_status == TRACE_FILE_END);
3708 if (num_out_reqs !=0 ) {
3709 printf ("num_out_reqs %d\n", num_out_reqs);
3710 CYCLIC_PRINT(dep_tab_index);
3712 RFS_ASSERT(num_out_reqs==0);
3715 printf ("trace starttime %d, trace_end_time %d trace_duration %d\n", trace_timestamp1, trace_timestamp2,
3716 trace_timestamp2 - trace_timestamp1);
3717 printf ("can_not_catch_speed_num_total %d can_not_catch_speed_num_last_10_seconds %d",
3718 can_not_catch_speed_num_total, can_not_catch_speed_num);
3719 printf ("total_profile.about: %s\n", total_profile.about);
3720 print_profile ("total_profile", &total_profile);
3722 //print_profile ("check_timeout", &check_timeout_profile);
3724 //print_profile ("adjust_play_window", &adjust_play_window_profile);
3726 print_profile ("execute_next_request_profile", &execute_next_request_profile);
3727 print_profile ("valid_get_nextop_profile", &valid_get_nextop_profile);
3728 print_profile ("invalid_get_nextop_profile", &invalid_get_nextop_profile);
3729 print_profile ("prepare_argument_profile", &prepare_argument_profile);
3730 print_profile ("biod_clnt_call_profile", &biod_clnt_call_profile);
3732 print_profile ("receive_next_reply_profile", &receive_next_reply_profile);
3733 print_profile ("valid_poll_and_get_reply_profile", &valid_poll_and_get_reply_profile);
3734 print_profile ("invalid_poll_and_get_reply_profile", &invalid_poll_and_get_reply_profile);
3735 print_profile ("decode_reply_profile", &decode_reply_profile);
3736 print_profile ("check_reply_profile", &check_reply_profile);
3737 print_profile ("fgets_profile", &fgets_profile);
3738 print_profile ("read_line_profile", &read_line_profile);
3739 print_profile ("read_trace_profile", &read_trace_profile);
3740 //print_profile ("add_create_object", &add_create_object_profile);
3743 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);
3747 int CYCLIC_SET_TAIL_TO(cyclic_index_t * index, int dest)
3749 cyclic_index_t indextmp, indextmp2;
3752 indextmp2 = indextmp;
3753 oldnum = CYCLIC_NUM(indextmp);
3755 if (! ((dest>=0) && (dest<indextmp.size))) {
3756 CYCLIC_PRINT(indextmp);
3757 printf("dest %d\n", dest);
3759 RFS_ASSERT ((dest>=0) && (dest<indextmp.size));
3761 indextmp2.tail = dest;
3762 num = CYCLIC_NUM(indextmp2);
3765 CYCLIC_PRINT(indextmp);
3766 CYCLIC_PRINT(indextmp2);
3767 printf("dest %d old_num %d num %d\n", dest, oldnum, num);
3769 RFS_ASSERT (num <= oldnum);
3775 for (i=0; i<500; i++) {
3776 printf ("*************************************************************\n");
3781 int CYCLIC_ASSERT (int i)
3784 if (!(dep_tab_index.tail == dep_window_index.tail)) {
3785 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);
3786 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);
3787 printf("pos %d\n", i);
3793 if (!((dep_window_index.head == dep_tab_index.head) ||
3794 CYCLIC_LESS(dep_tab_index, dep_window_index.head, dep_tab_index.head ) )) {
3795 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);
3796 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);
3797 printf("pos %d\n", i);
3802 for (i=0, j=0; i<max_biod_reqs; i++) {
3803 if (biod_reqp[i].in_use == 1)
3807 RFS_ASSERT (num_out_reqs==j);
3810 RFS_ASSERT ((dep_window_index.head == dep_tab_index.head) ||
3811 CYCLIC_LESS(dep_tab_index, dep_window_index.head, dep_tab_index.head ));