TBBT/trace_play/sfs_c_chd.3thread.c

   1 /* Try to change thread scheduling and uses three threads */
   2 #ifndef lint
   3 static char sfs_c_chdSid[] = "@(#)sfs_c_chd.c   2.1     97/10/23";
   4 #endif
   5
   6 /*
   7  *   Copyright (c) 1992-1997,2001 by Standard Performance Evaluation Corporation
   8  *      All rights reserved.
   9  *              Standard Performance Evaluation Corporation (SPEC)
  10  *              6585 Merchant Place, Suite 100
  11  *              Warrenton, VA 20187
  12  *
  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.
  16  *
  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.
  20  *
  21  *      The source code is provided to the user or company under the license
  22  *      agreement for the SPEC Benchmark Suite for this product.
  23  */
  24
  25 /*****************************************************************
  26  *                                                               *
  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.              *
  33  *                                                               *
  34  *****************************************************************/
  35
  36 /*
  37  * -------------------------- sfs_c_chd.c -------------------------
  38  *
  39  *      The sfs child.  Routines to initialize child parameters,
  40  *      initialize test directories, and generate load.
  41  *
  42  *.Exported_Routines
  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,
  47  *                              sfs_file_type);
  48  *      int check_access(struct *stat)
  49  *      int check_fh_access();
  50  *
  51  *.Local_Routines
  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);
  57  *      int do_op(void);
  58  *      int op(int);
  59  *
  60  *.Revision_History
  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
  64  *                                      instead of BTDT.
  65  *      04-Jan-92       Pawlowski       Added raw data dump hooks.
  66  *      16-Dec-91       Wittle          Created.
  67  */
  68
  69
  70 /*
  71  * -------------------------  Include Files  -------------------------
  72  */
  73
  74 /*
  75  * ANSI C headers
  76  */
  77 #include <stdio.h>
  78 #include <stdlib.h>
  79 #include <string.h>
  80 #include <errno.h>
  81 #include <math.h>
  82 #include <signal.h>
  83
  84 #include <sys/types.h>
  85 #include <sys/stat.h>
  86
  87 #include <unistd.h>
  88
  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"
  94
  95 extern struct hostent   *Server_hostent;
  96
  97 #define PROB_SCALE 1000L
  98 #define _M_MODULUS 2147483647L /* (2**31)-1 */
  99
 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
 104
 105
 106 /*
 107  * -----------------------  External Definitions  -----------------------
 108  */
 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);
 114
 115 /* forward definitions for local functions */
 116 static int init_rpc(void);
 117
 118 /* RFS: forward definitions for local functions */
 119 void init_ops(void);
 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);
 146
 147 /*
 148  * -------------  Per Child Load Generation Rate Variables  -----------
 149  */
 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 */
 158
 159 static char io_buf[BUFSIZ];     /* io buffer for print out messages */
 160
 161 char * sfs_Myname;
 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 */
 168 uid_t Real_uid;
 169 gid_t Cur_gid;
 170 uid_t Cur_uid;
 171 /* as long as the inital value is different, then it's OK */
 172 int recv_num = 0;
 173 int timeout_num = 0;
 174 int send_num = 0;
 175 int exit_flag = 0;
 176 int async_rpc_sem;
 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];
 180
 181 /*
 182  * -------------------------  SFS Child  -------------------------
 183  */
 184
 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,
 189                                                                                                         22, 19};
 190 void print_usage(int pos, int argc, char ** argv)
 191 {
 192         int i;
 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]);
 200         }
 201         printf ("\n");
 202         exit;
 203 }
 204
 205 void print_cyclic_buffers ()
 206 {
 207         CYCLIC_PRINT(memory_trace_index);
 208         CYCLIC_PRINT(dep_tab_index);
 209         CYCLIC_PRINT(dep_window_index);
 210 }
 211
 212 void add_to_dep_tab(int i)
 213 {
 214         char * trace_fh;
 215         fh_map_t * fh_map_entry;
 216         dep_tab_t * ent;
 217
 218     trace_fh = strstr (memory_trace[i].line, "fh");
 219     if (!trace_fh)
 220         printf ("memory_trace[%d].line %s\n", i, memory_trace[i].line);
 221     RFS_ASSERT (trace_fh);
 222     trace_fh += 3;
 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 ++;
 226                 return;
 227         }
 228     if (fh_map_entry)
 229         req_num_with_init_fh ++;
 230     else
 231         req_num_with_new_fh ++;
 232
 233         RFS_ASSERT (!CYCLIC_FULL(dep_tab_index));
 234         ent = &(dep_tab[dep_tab_index.head]);
 235
 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;
 241 #endif
 242     ent->line = memory_trace[i].line;
 243     init_dep_tab_entry(dep_tab_index.head);
 244
 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);
 249 }
 250
 251 void init_profile_variables ()
 252 {
 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);
 270 }
 271
 272 static char trace_file[256]="anon-lair62-011130-1200.txt";
 273 int print_memory_usage()
 274 {
 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));
 298
 299
 300 }
 301
 302 void recv_thread()
 303 {
 304         int last_print_time = -1;
 305         int busy_flag;
 306
 307         while (send_num ==0) {
 308                 usleep(1000);
 309         }
 310
 311         //while (!CYCLIC_EMPTY(dep_tab_index)) {
 312         while (!exit_flag) {
 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;
 319                                 RFS_ASSERT (0);
 320                         } else
 321                                 recv_num_before_10_seconds = recv_num;
 322                 }
 323                 //start_profile (&check_timeout_profile);
 324                 check_timeout();
 325                 //end_profile (&check_timeout_profile);
 326
 327                 pthread_yield();
 328                 //usleep(1000);
 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);
 335 #endif
 336 #ifdef SEND_RECEIVE_EQUAL_PRIORITY_POLICY
 337                 busy_flag = IDLE;
 338                 while (receive_next_reply(busy_flag)!=-1) {
 339                         busy_flag = BUSY;
 340                 }
 341 #endif
 342                 end_profile (&receive_next_reply_profile);
 343         }
 344         printf ("<<<< recv thread EXIT\n");
 345         exit_flag = 2;
 346 }
 347
 348 int io_thread ()
 349 {
 350 /* number of seconds the I/O thread pauses after each time trying to read the requests */
 351 #define IO_THREAD_PAUSE_TIME 1
 352
 353         int i;
 354         int j = 0;
 355
 356         disk_io_status = read_trace ();
 357         while (disk_io_status == TRACE_BUF_FULL) {
 358
 359                 usleep (10000);
 360         if ((j++%1000)==0) {
 361                 printf("&&&&&&&&&& io thread, sleep %d seconds\n", j/100);
 362         }
 363
 364                 disk_io_status = read_trace ();
 365                 //printf ("io_thread, after read_trace, disk_index %d\n", disk_index);
 366
 367 #ifdef SEQUEN_READ
 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));
 370                 }
 371 #endif
 372                 //printf ("***************** IO THREAD SLEEP 1 s\n");
 373                 //print_cyclic_buffers();
 374                 //pthread_yield();
 375         }
 376         RFS_ASSERT (disk_io_status == TRACE_FILE_END);
 377         printf("io_thread EXIT\n");
 378 }
 379
 380 int execute_thread()
 381 {
 382         int i;
 383         struct timeval playstart_time, playend_time;
 384
 385         sleep (10);             /* first let io_thread to run for a while */
 386         printf ("trace_play\n");
 387
 388         gettimeofday(&playstart_time, NULL);
 389
 390         init_time_offset();
 391         trace_play ();
 392
 393         gettimeofday(&playend_time, NULL);
 394
 395         {
 396                 int usec, sec;
 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)
 403                         print_result();
 404                 else
 405                         printf ("the trace play time %d is less than WARMUP_TIME %d, no statistical results\n");
 406         }
 407 #ifdef RECV_THREAD
 408         exit_flag = 1;
 409         while (exit_flag == 1) {
 410                 usleep (1000);
 411         }
 412 #endif
 413
 414     clnt_destroy(NFS_client);
 415     biod_term();
 416 }
 417
 418 int init_thread ()
 419 {
 420         pthread_attr_t  attr;
 421         int arg;
 422         int ret = 0;
 423         pthread_t io_thread_var;
 424 #ifdef RECV_THREAD
 425         pthread_t recv_thread_var;
 426 #endif
 427         pthread_t execute_thread_var;
 428
 429         ret = pthread_attr_init (&attr);
 430         if (ret!=0) {
 431                 perror("pthread_attr_init attr");
 432                 return ret;
 433         }
 434 #ifdef IO_THREAD
 435         ret = pthread_create (&(io_thread_var), &attr, &io_thread, (void *)&arg );
 436         if (ret!=0) {
 437                 perror("io_pthread_attr_init");
 438                 return ret;
 439         }
 440 #endif
 441
 442 #ifdef RECV_THREAD
 443         ret = pthread_create (&(recv_thread_var), &attr, &recv_thread, (void *)&arg );
 444         if (ret!=0) {
 445                 perror("recv_pthread_attr_init");
 446                 return ret;
 447         }
 448 #endif
 449
 450 /*
 451         ret = pthread_create (&(execute_thread_var), &attr, &execute_thread, (void *)&arg );
 452         if (ret!=0) {
 453                 perror("io_pthread_attr_init");
 454                 return ret;
 455         }
 456 */
 457 }
 458
 459 void init_buffers()
 460 {
 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);
 464 }
 465
 466 int main(int argc, char ** argv)
 467 {
 468         extern char * optarg;
 469         int i;
 470         struct timeval in={1000000, 100};
 471
 472         init_profile_variables();
 473         if ((argc==1) || (argc==2 && !strcmp(argv[1],"-help"))) {
 474                 print_usage(0, argc, argv);
 475                 exit(0);
 476         }
 477         if (!strcmp(argv[1], "-pair_write")) {
 478                 if (argc==3)
 479                         strcpy(trace_file, argv[2]);
 480                 else
 481                         strcpy(trace_file, "stdin");
 482                 pair_write(trace_file);
 483                 exit(0);
 484         }
 485         if (!strcmp(argv[1], "-pair_trace")) {
 486                 if (argc==3)
 487                         strcpy(trace_file, argv[2]);
 488                 else
 489                         strcpy(trace_file, "stdin");
 490                 pair_trace(trace_file);
 491                 exit(0);
 492         }
 493         if (!strcmp(argv[1], "-check_aging")) {
 494                 if (argc!=3) {
 495                         print_usage(3, argc, argv);
 496                         exit(0);
 497                 }
 498                 strcpy(trace_file, argv[2]);
 499                 check_aging (trace_file);
 500                 exit(0);
 501         }
 502         if (!strcmp(argv[1], "-check_statistics")) {
 503                 if (argc!=3) {
 504                         print_usage(1, argc, argv);
 505                         exit(0);
 506                 }
 507                 strcpy(trace_file, argv[2]);
 508                 memset(fh_htable, 0, sizeof (fh_htable));
 509                 check_statistics (trace_file);
 510                 exit(0);
 511         }
 512
 513         if (argc!=6) {
 514                 print_usage(2, argc, argv);
 515                 exit(0);
 516         }
 517
 518         PLAY_SCALE = atoi (argv[4]);
 519         RFS_ASSERT (PLAY_SCALE >=1 && PLAY_SCALE <=10000);
 520
 521         WARMUP_TIME = atoi (argv[5]);
 522         RFS_ASSERT (WARMUP_TIME >=0 && WARMUP_TIME <=1000);
 523
 524         print_memory_usage();
 525         check_clock();
 526     getmyhostname(lad_hostname, HOSTNAME_LEN);
 527
 528     init_ops();
 529         /*
 530          * Get the uid and gid information.
 531          */
 532         Real_uid = getuid();
 533         Cur_gid = getgid();
 534         //Real_uid = 513;
 535         //Cur_gid = 513;
 536
 537         Nfs_timers = Nfs_udp_timers;
 538
 539         init_semaphores();
 540         init_file_system ();
 541         init_signal();
 542         init_play (argv[1]);
 543         //init_play ("capella:/p5/RFSFS");
 544         init_fh_map();
 545         read_fh_map (argv[3]);
 546         //read_fh_map ("fh-path-map-play");
 547         strcpy(trace_file, argv[2]);
 548
 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
 552  */
 553
 554         init_global_variables();
 555         init_buffers();
 556         init_thread();
 557         pthread_yield();
 558         execute_thread();
 559 }
 560
 561 int init_global_variables()
 562 {
 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));
 565 }
 566
 567 int init_semaphores()
 568 {
 569         async_rpc_sem = dest_and_init_sem (ASYNC_RPC_SEM_KEY, 1, "async_rpc_sem");
 570 }
 571
 572 void init_ops (void)
 573 {
 574         Ops = nfsv3_Ops;
 575         nfs_version = NFS_V3;
 576 }
 577
 578 /* Set up the signal handlers for all signals */
 579 void init_signal()
 580 {
 581 #if (defined(_XOPEN_SOURCE) || defined(USE_POSIX_SIGNALS))
 582         struct sigaction sig_act, old_sig_act;
 583
 584         /* use XOPEN signal handling */
 585
 586         sig_act.sa_handler = generic_catcher;
 587         (void)sigemptyset(&sig_act.sa_mask);
 588         sig_act.sa_flags = 0;
 589
 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");
 594             exit(135);
 595         }
 596
 597         sig_act.sa_handler = sfs_cleanup;
 598         if (sigaction(SIGTERM,&sig_act,&old_sig_act) != 0)  {
 599             perror("sigaction failed: SIGTERM");
 600             exit(137);
 601         }
 602 #else
 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);
 607 #endif
 608 }
 609
 610 void
 611 init_play (
 612     char        * mount_point)          /* Mount point for remote FS */
 613 {
 614     char        namebuf[NFS_MAXNAMLEN] = "trace_play";  /* unique name for this program */
 615     CLIENT *    mount_client_ptr;       /* Mount client handle */
 616
 617         if (!rfs_debug);
 618         (void) setvbuf(stderr, io_buf, _IOLBF, BUFSIZ);
 619
 620     sfs_Myname = namebuf;
 621
 622     /*
 623      * May require root priv to perform bindresvport operation
 624      */
 625     mount_client_ptr = lad_getmnt_hand(mount_point);
 626     if (mount_client_ptr == NULL) {
 627                 exit(145);
 628     }
 629
 630     /*
 631      * should be all done doing priv port stuff
 632      */
 633
 634     if (init_rpc() == -1) {
 635                 (void) fprintf(stderr, "%s: rpc initialization failed\n", sfs_Myname);
 636                 (void) generic_kill(0, SIGINT);
 637                 exit(146);
 638     }
 639
 640
 641     /*
 642      * finish all priv bindresvport calls
 643      * reset uid
 644      */
 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");
 649     }
 650
 651     init_mount_point(0, mount_point, mount_client_ptr);
 652
 653
 654     /*
 655      * Cleanup client handle for mount point
 656      */
 657     clnt_destroy(mount_client_ptr);
 658
 659         init_counters();
 660 }
 661
 662 #ifdef REDUCE_MEMORY_TRACE_SIZE
 663 void inline format_line (char * line_before, char * line)
 664 {
 665         char * pv = line_before;
 666         char * pl = line;
 667         char * p;
 668         int i;
 669
 670         //printf("format_line before %s\n", line_before);
 671         p = strstr (pv, "fh");
 672         while (p!=NULL) {
 673                 while (pv<=p)
 674                         *pl++ = *pv++;
 675                 *pl++ = *pv++;
 676                 if (*pv==2) {
 677                         *pl++ = *pv++;
 678                 }
 679                 *pl++ = *pv++;
 680                 i = 0;
 681                 while (*pv !=' ') {
 682                         RFS_ASSERT ((*pv >='0' && *pv <='9') || (*pv >='a' && *pv<='f'));
 683                         *pl++ = *pv++;
 684                         i++;
 685                 }
 686                 RFS_ASSERT ((i==48) || (i==40) || (i==24));
 687                 while (i<48) {
 688                         *pl++ = '0';
 689                         i++;
 690                 }
 691                 p = strstr (pv, "fh");
 692         }
 693         while ((*pv)!='\0') {
 694                 *pl++ = *pv++;
 695         }
 696         //printf("format_line after %s\n", line);
 697 }
 698
 699 char * read_line (int disk_index)
 700 {
 701         static FILE * fp=NULL;
 702         static int start=0;
 703         static int start_disk_index=0;
 704         int i;
 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)
 710
 711         static char line_buf[READ_LINE_BUF_SIZE][READ_LINE_LENGTH];
 712         char varfh_line_buf[READ_LINE_LENGTH];
 713
 714         start_profile (&read_line_profile);
 715
 716         if (fp==NULL) {
 717                 if (strcmp(trace_file, "stdin")) {
 718                         fp = fopen(trace_file, "r");
 719
 720                         if (strstr(trace_file, ".varfh")) {
 721                                 varfh_flag = 1;
 722                         };
 723                         if (strstr(trace_file, ".fmt1")) {
 724                                 TRACE_COMMAND_REPLY_FLAG_POS += 12;
 725                                 TRACE_VERSION_POS +=12;
 726                                 TRACE_MSGID_POS +=12;
 727                                 TRACE_FH_SIZE =48;
 728                         }
 729                         if (!fp) {
 730                                 printf("can not open files %s\n", fp);
 731                                 perror("open");
 732                         }
 733                 } else {
 734                         fp = stdin;
 735                 }
 736                 RFS_ASSERT (fp!=NULL);
 737                 for (i=0; i<READ_LINE_BUF_SIZE; i++) {
 738                         start_profile(&fgets_profile);
 739                         if (varfh_flag) {
 740                                 if (!fgets(varfh_line_buf, READ_LINE_LENGTH, fp)) {
 741                                         RFS_ASSERT (0);
 742                                 }
 743                                 format_line (varfh_line_buf, line_buf[i]);
 744                         } else {
 745                                 if (!fgets(line_buf[i], READ_LINE_LENGTH, fp)) {
 746                                         RFS_ASSERT (0);
 747                                 }
 748                         }
 749                         end_profile(&fgets_profile);
 750                         //printf ("read_line, line_buf[%d]:%s", i, line_buf[i]);
 751                 }
 752         }
 753
 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);
 757         }
 758         RFS_ASSERT (disk_index <= start_disk_index+READ_LINE_BUF_SIZE)
 759         if (disk_index==(start_disk_index+READ_LINE_BUF_SIZE)) {
 760                 if (finish_flag) {
 761                         return NULL;
 762                 }
 763                 start_profile(&fgets_profile);
 764                 if (!fgets(line_buf[start], READ_LINE_LENGTH, fp)) {
 765                         end_profile(&fgets_profile);
 766                         finish_flag = 1;
 767                         return NULL;
 768                 }
 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;
 772                 start_disk_index ++;
 773         }
 774         RFS_ASSERT (disk_index < start_disk_index+READ_LINE_BUF_SIZE)
 775         i = (start+disk_index-start_disk_index)%READ_LINE_BUF_SIZE;
 776
 777 /*
 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);
 781         }
 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));
 785 */
 786
 787         end_profile (&read_line_profile);
 788         return (line_buf[i]);
 789 }
 790
 791 #define OPS_FLAG_INC 0
 792 #define OPS_FLAG_PRINT 1
 793 int read_write_fh_statistics (int flag, char * buf, int timestamp)
 794 {
 795         static FILE * fp = NULL;
 796         char * p;
 797         char c;
 798         if (!fp) {
 799                 fp = fopen ("read_write_fh.output", "w");
 800                 RFS_ASSERT (fp);
 801         }
 802         if (flag == OPS_FLAG_INC) {
 803                 p = strstr (buf, "fh");
 804                 RFS_ASSERT (p);
 805                 c = p[40+3];
 806                 p[40+3]=0;
 807                 fprintf(fp, "%s\n", p+3+24);
 808                 p[40+3]=c;
 809         };
 810         if (flag == OPS_FLAG_PRINT) {
 811                 int disk_index = (int) buf;
 812                 fprintf(fp, "###### disk_index %d timestamp %d\n", disk_index, timestamp);
 813         }
 814 }
 815
 816 int write_statistics(int flag, char * buf, char * reply_buf, int trace_status)
 817 {
 818         static FILE * fp = NULL;
 819         int pre_size, size, count;
 820         char * p = reply_buf;
 821         if (!fp) {
 822                 fp = fopen ("write.output", "w");
 823                 RFS_ASSERT (fp);
 824         }
 825         if (flag == OPS_FLAG_INC) {
 826                 p = strstr (p, "pre-size");
 827                 RFS_ASSERT (p);
 828                 sscanf (p, "pre-size %x", &pre_size);
 829                 p += strlen("pre-size");
 830                 p = strstr (p, "size");
 831                 RFS_ASSERT (p);
 832                 sscanf (p, "size %x", &size);
 833                 p = strstr (p, "count");
 834                 if (!p)
 835                         fprintf (fp, "%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
 836                 RFS_ASSERT (p);
 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);
 839         }
 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);
 844         }
 845 }
 846
 847 void ops_statistics (int ops_flag, int proc, int timestamp)
 848 {
 849         static FILE * fp = NULL;
 850         static struct {
 851                 int count;
 852                 int count_K;
 853                 int update_flag;
 854                 char name[32];
 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"}};
 861
 862         if (ops_flag == OPS_FLAG_INC) {
 863                 RFS_ASSERT (proc>=0 && proc<NOPS);
 864                 ops[proc].count ++;
 865                 if (ops[proc].count == 1000) {
 866                         ops[proc].count_K ++;
 867                         ops[proc].count = 0;
 868                 }
 869         }
 870         if (ops_flag == OPS_FLAG_PRINT) {
 871                 int i;
 872                 int update_K=0, update=0, total_K=0, total=0;
 873                 float f1, f2;
 874                 int disk_index = proc;
 875
 876                 if (!fp) {
 877                         fp = fopen ("mix.output", "w");
 878                         RFS_ASSERT (fp);
 879                 }
 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;
 886                         }
 887                 }
 888                 update_K += update/1000;
 889                 update = update%1000;
 890                 total_K += total/1000;
 891                 total = total%1000;
 892
 893                 f1 = total_K;
 894                 f1 = f1*1000+total;
 895                 for (i=0; i<NOPS; i++) {
 896                         f2 = ops[i].count_K;
 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);
 900                 }
 901                 f2 = update_K;
 902                 f2 = f2*1000+update;
 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);
 909         }
 910 }
 911
 912
 913 void truncate_statistics (int flag, int proc, char * buf, char * reply_buf)
 914 {
 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;
 929         char * p;
 930         char * trace_fh;
 931         int pre_size, size, count;
 932         struct generic_entry * ent;
 933
 934         if (flag == OPS_FLAG_PRINT) {
 935                 int disk_index = proc;
 936                 int timestamp = (int)buf;
 937                 if (!fp) {
 938                         fp = fopen ("truncate.output", "w");
 939                         RFS_ASSERT (fp);
 940                 }
 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);
 947                 return;
 948         }
 949
 950         p = strstr (&buf[TRACE_MSGID_POS], "fh");
 951         RFS_ASSERT (p);
 952         p+=3;
 953         trace_fh = p;
 954
 955         if (proc==SETATTR) {
 956                 p = strstr (buf, " size ");
 957         } else {
 958                 RFS_ASSERT (proc==WRITE);
 959                 p = strstr (reply_buf, " ftype 1 ");
 960                 RFS_ASSERT (p);
 961                 p = strstr (p, " size ");
 962                 RFS_ASSERT (p);
 963                 if (strstr(p, " ftype 1 ")) {
 964                         fprintf (fp, "#### %s%s\n", buf, reply_buf);
 965                         fprintf (stderr, "#### %s%s\n", buf, reply_buf);
 966                 }
 967                 RFS_ASSERT (!strstr(p, " ftype 1 "));
 968         }
 969         if (!p) {
 970                 no_size_num ++;
 971                 return;
 972         }
 973         have_size_num ++;
 974
 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);
 979         }
 980
 981         RFS_ASSERT (size >=0 && size <2000000000);
 982         ent = generic_lookup (trace_fh+24, TRACE_FH_SIZE2, 0, fh_htable, FH_HTABLE_SIZE);
 983         if (ent) {
 984                 if (ent->key3 != size) {
 985                         if (proc==SETATTR) {
 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) {
 989                                         truncate_num ++;
 990                                         truncate_size += ent->key3 - size;
 991                                         truncate_block_num += (ent->key3+BLOCK_SIZE-1)/BLOCK_SIZE;
 992                                         if (size!=0) {
 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;
 996                                         }
 997                                         if (truncate_size > 1000000000) {
 998                                                 truncate_KB += truncate_size/1000;
 999                                                 truncate_size %= 1000;
1000                                         }
1001                                 } else {
1002                                         padding_num ++;
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;
1009                                         }
1010                                 }
1011                         }
1012                         ent->key3 = size;
1013                 }else
1014                         equal_size_num++;
1015         } else {
1016                 generic_insert(trace_fh+24, TRACE_FH_SIZE2, size, fh_htable, FH_HTABLE_SIZE);
1017                 first_size_num ++;
1018         }
1019 };
1020
1021 int get_timestamp_usec (char * buf)
1022 {
1023         char str[128];
1024         int ret;
1025         strncpy(str, buf, 100);
1026         RFS_ASSERT (str[10]=='.');
1027         RFS_ASSERT (str[17]==' ');
1028         str[17]=0;
1029         ret = atoi(&str[11]);
1030         RFS_ASSERT (ret >=0 && ret <=999999);
1031         return ret;
1032 }
1033
1034 int get_timestamp_sec (char * buf)
1035 {
1036         char str[128];
1037         int ret;
1038         strncpy(str, buf, 100);
1039         RFS_ASSERT (str[10]=='.');
1040         str[10]=0;
1041         ret = atoi(str);
1042         RFS_ASSERT (ret >1000000000 && ret <2000000000);
1043         return ret;
1044 }
1045
1046 int check_aging (char * tracefile)
1047 {
1048         int disk_index=-1;
1049         char *buf;
1050         char *reply_buf;
1051         int i;
1052         int trace_status;
1053         int debug = 0;
1054         int nfs3proc, msgid, proc;
1055
1056         while ((buf=read_line(++disk_index))!=NULL) {
1057                 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1058                         continue;
1059                 if (buf[TRACE_VERSION_POS]!='3')
1060                         continue;
1061                 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1062
1063                 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1064
1065                 proc = nfs3proc_to_rfsproc[nfs3proc];
1066                 ops_statistics (OPS_FLAG_INC, proc, -1);
1067
1068                 switch (proc) {
1069                 int off, count, size;
1070                 char * t;
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;
1075                 case WRITE:
1076                         t = buf;
1077                         t = strstr (t, "off");
1078                 RFS_ASSERT (t);
1079                     t+=4;
1080                         sscanf (t, "%x", &off);
1081                         RFS_ASSERT (off>=0 && off<0x7FFFFFFF)
1082                         t = strstr (t, "count");
1083                     RFS_ASSERT (t);
1084                         t+=6;
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);
1089                         break;
1090                 case SETATTR:
1091                         t = strstr (buf, " size ");
1092                         if (t) {
1093                                 sscanf (t, " size %x", &size);
1094                                 printf ("%s size %x\n", "setattr", size);
1095                         }
1096                 }
1097                 if ((disk_index%10000)==0) {
1098                         fprintf(stderr, "%d disk trace passed\n", disk_index);
1099                 }
1100         };
1101
1102         fprintf(stderr, "%d disk trace parsed\n", disk_index);
1103         ops_statistics (OPS_FLAG_PRINT, disk_index, -1);
1104 }
1105
1106
1107 int check_statistics (char * tracefile)
1108 {
1109         int disk_index=-1;
1110         char *buf;
1111         char *reply_buf;
1112         int i;
1113         char * p;
1114         int trace_status;
1115         int debug = 0;
1116         int nfs3proc, msgid, proc;
1117         static int last_timestamp_sec = -1;
1118         int timestamp_sec;
1119         int memory_trace_size = 0;
1120
1121         while ((buf=read_line(++disk_index))!=NULL) {
1122                 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1123                         continue;
1124                 if (buf[TRACE_VERSION_POS]!='3')
1125                         continue;
1126                 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1127
1128                 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1129                 timestamp_sec = get_timestamp_sec(buf);
1130
1131                 proc = nfs3proc_to_rfsproc[nfs3proc];
1132                 ops_statistics (OPS_FLAG_INC, proc, -1);
1133
1134                 if (proc!= WRITE && proc!=SETATTR && proc!=READ) {
1135                         continue;
1136                 }
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));
1142                 if (debug)
1143                         printf("read line disk_index %d %s\n", disk_index, buf);
1144
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);
1148                         if (debug)
1149                                 printf("searching for reply: read line %s\n", reply_buf);
1150                         if (!reply_buf)
1151                                 break;
1152                 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1153                         p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
1154                         RFS_ASSERT (p);
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);
1160                                                 if (proc == WRITE)
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);
1164                                         }
1165                                 };
1166                 }
1167                 }
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 ++;
1172                 }
1173
1174 #if     0       /* commented out by G. Jason Peng */
1175                 if *
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);
1178                         exit (0);
1179                 }
1180 #endif
1181
1182                 memory_trace_size ++;
1183
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;
1192                 }
1193 /*
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);
1198                 }
1199 */
1200         };
1201
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);
1207 }
1208
1209
1210 /* This routine output all the requests, together with their replies */
1211 int pair_trace (char * tracefile)
1212 {
1213         int disk_index=-1;
1214         char *buf;
1215         char *reply_buf;
1216         int i;
1217         char * p;
1218         int trace_status;
1219         int debug = 0;
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;
1223         FILE * outputfp;
1224         char output_file[1024];
1225
1226         strcpy (output_file, tracefile);
1227         strcat (output_file, ".pair");
1228         outputfp = fopen (output_file, "w");
1229         RFS_ASSERT (outputfp);
1230
1231         while ((buf=read_line(++disk_index))!=NULL) {
1232                 if (disk_index == 258)
1233                         f();
1234                 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1235                         continue;
1236                 if (buf[TRACE_VERSION_POS]!='3')
1237                         continue;
1238                 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1239
1240                 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1241                 ops[nfs3proc]++;
1242
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));
1247                 if (debug)
1248                         printf("read line disk_index %d %s\n", disk_index, buf);
1249                 fprintf (outputfp, "%s\n", buf);
1250
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);
1254                         if (debug)
1255                                 printf("searching for reply: read line %s\n", reply_buf);
1256                         if (!reply_buf)
1257                                 break;
1258                 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1259                         p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
1260                         RFS_ASSERT (p);
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);
1264                                         if (debug)
1265                                                 fprintf(stderr, "reply found trace_status %d\n", find_reply_status(reply_buf));
1266                                         break;
1267                                 };
1268                 }
1269                 }
1270
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 ++;
1275                 }
1276
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);
1279                         exit (0);
1280                 }
1281
1282                 memory_trace_size ++;
1283
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 );
1286         };
1287
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);
1290
1291 }
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
1294  */
1295 int pair_write (char * tracefile)
1296 {
1297         int disk_index=-1;
1298         char *buf;
1299         char *reply_buf;
1300         int i;
1301         char * p;
1302         int trace_status;
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;
1307
1308         while ((buf=read_line(++disk_index))!=NULL) {
1309                 if (buf[TRACE_COMMAND_REPLY_FLAG_POS]!='C')
1310                         continue;
1311                 if (buf[TRACE_VERSION_POS]!='3')
1312                         continue;
1313                 sscanf (&buf[TRACE_MSGID_POS], "%x %x", &msgid, &nfs3proc);
1314
1315                 RFS_ASSERT (nfs3proc>=0 && nfs3proc<NFS3_PROCEDURE_COUNT);
1316                 ops[nfs3proc]++;
1317
1318                 if (!strstr(buf, "write"))
1319                         continue;
1320
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);
1327
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;
1331
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);
1339                         if (!reply_buf)
1340                                 break;
1341                 if (reply_buf[TRACE_COMMAND_REPLY_FLAG_POS]=='R') {
1342                         p = strchr (&reply_buf[TRACE_MSGID_POS], ' ');
1343                         RFS_ASSERT (p);
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));
1349                                                 //break;
1350                         trace_status = find_reply_status(reply_buf);
1351                                         if (trace_status == NFS3_OK) {
1352                                                 p = strstr (p, "pre-size");
1353                                                 RFS_ASSERT (p);
1354                                                 sscanf (p, "pre-size %x", &pre_size);
1355                                                 p += strlen("pre-size");
1356                                                 p = strstr (p, "size");
1357                                                 RFS_ASSERT (p);
1358                                                 sscanf (p, "size %x", &size);
1359                                                 p = strstr (p, "count");
1360                                                 if (!p)
1361                                                         printf ("%s status %x pre-size %x size %x count %x\n", buf, trace_status, pre_size, size, count);
1362                                                 RFS_ASSERT (p);
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);
1365                                                 break;
1366                                         }
1367                                 };
1368                 }
1369                 }
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 ++;
1374                 }
1375
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);
1379                         exit (0);
1380                 }
1381 #endif
1382
1383                 memory_trace_size ++;
1384
1385                 /*
1386                 if (memory_trace_size >= MAX_MEMORY_TRACE_LINES) {
1387                         fprintf (stderr, "memory trace size %d is not enough\n", MAX_MEMORY_TRACE_LINES);
1388                         break;
1389                 }
1390                 */
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 );
1393         };
1394
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);
1397
1398 }
1399
1400 #ifdef notdef
1401 /* This function is not finished writing */
1402 int calculate_performance()
1403 {
1404         char *buf;
1405         char *reply_buf;
1406         int i;
1407         char * p;
1408         int debug = 0;
1409
1410 typedef struct {
1411         struct timeval start;
1412         struct timeval stop;
1413         int trace_status;
1414         int op;
1415 } trace_performance_ent_t;
1416
1417         struct timeval req_time;
1418         struct timeval reply_time;
1419
1420         trace_performance_ent_t * ent = NULL;
1421
1422         while (!CYCLIC_FULL(memory_trace_index)) {
1423
1424                 if (ent!=NULL && (ent->trace_status == NFS3ERR_RFS_MISS))
1425                         buf = reply_buf;
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;
1431                 }
1432
1433                 get_timestamp (&ent->req_time, buf);
1434                 if (MAX_COMMAND_REPLY_DISTANCE ==1) {
1435                         ent->trace_status == NFS3ERR_RFS_MISS;
1436                 } else {
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;
1441                         } else {
1442                                 get_timestamp (&ent->reply_time, buf);
1443                                 ent->trace_status = find_reply_status(reply_buf);
1444                         }
1445                 }
1446         }
1447 }
1448 #endif
1449
1450 int read_trace ()
1451 {
1452         char *buf;
1453         char *reply_buf;
1454         int i;
1455         char * p;
1456         int debug = 0;
1457         memory_trace_ent_t * ent=NULL;
1458
1459         start_profile (&read_trace_profile);
1460
1461         while (!CYCLIC_FULL(memory_trace_index)) {
1462                 if (ent!=NULL && (ent->trace_status == NFS3ERR_RFS_MISS))
1463                         buf = reply_buf;
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;
1469                 }
1470
1471                 if (rfs_debug)
1472                         printf ("disk_index %d %s\n", disk_index, buf);
1473
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);
1480                 } else
1481                         trace_timestamp2 = get_timestamp_sec (buf);
1482
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;
1487
1488                 if (MAX_COMMAND_REPLY_DISTANCE ==1) {
1489                         ent->trace_status == NFS3ERR_RFS_MISS;
1490                 } else {
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;
1495                         } else {
1496                                 ent->trace_status = find_reply_status(reply_buf);
1497                         }
1498                 };
1499
1500                 if (ent->trace_status == NFS3ERR_RFS_MISS)
1501                         missing_reply_num ++;
1502
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);
1506                                 exit (0);
1507                         }
1508                 }
1509
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);
1516                                 if (p==NULL) {
1517                                         printf("skip line disk_index %d %s \n", disk_index, buf);
1518                                         continue;
1519                                 }
1520                                 memcpy(ent->reply_trace_fh, p, TRACE_FH_SIZE);
1521                         } else
1522                                 memset(ent->reply_trace_fh, 0, TRACE_FH_SIZE);
1523                 }
1524
1525                 add_to_dep_tab(memory_trace_index.head);
1526
1527                 if (((disk_index+1)%20000)==0) {
1528                         fprintf(stderr, "%d disk trace parsed \n", disk_index+1);
1529                 };
1530         };
1531
1532         end_profile (&read_trace_profile);
1533         return TRACE_BUF_FULL;
1534 }
1535 #else   /* not defined REDUCE_MEMORY_TRACE_SIZE */
1536 int read_trace ()
1537 {
1538         FILE * fp;
1539         char buf[1024];
1540         // char * t=buf;
1541         int disk_index=0;
1542
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));
1549
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 ++;
1554
1555                 if (memory_trace_size >= MAX_MEMORY_TRACE_LINES) {
1556                         fprintf (stderr, "memory trace size %d is not enough\n", MAX_MEMORY_TRACE_LINES);
1557                         break;
1558                 }
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);
1561                 disk_index ++;
1562         }
1563
1564         fprintf(stderr, "total %d disk lines %d memory lines \n", disk_index, memory_trace_size );
1565 }
1566 #endif
1567
1568
1569 #ifdef REDUCE_MEMORY_TRACE_SIZE
1570 inline int disk_index_to_memory_index (int disk_index)
1571 {
1572         static int memory_index = 0;
1573
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);
1580                 }
1581         };
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);
1585                 }
1586         };
1587
1588         RFS_ASSERT (disk_index == memory_trace[memory_index].disk_index);
1589         return memory_index;
1590 }
1591 #else
1592 #define disk_index_to_memory_index(disk_index)  disk_index
1593 #endif
1594
1595 #define get_line_by_disk_index(disk_index) \
1596         memory_trace[disk_index_to_memory_index(disk_index)].line
1597
1598 inline char * find_reply_line (char * command_line, int cur_disk_index)
1599 {
1600         int i;
1601         char * line;
1602         char * p;
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], ' ');
1608             RFS_ASSERT (p);
1609                         if (!strncmp(&line[TRACE_MSGID_POS], &command_line[TRACE_MSGID_POS], p-&(line[TRACE_MSGID_POS])))
1610                                 return line;
1611                 }
1612         }
1613         return NULL;
1614 }
1615
1616 inline int find_reply_status (char * line)
1617 {
1618         char * p;
1619         int i=0;
1620
1621         if (rfs_debug)
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);
1625         };
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"))
1629                 return NFS3_OK;
1630         if (strstr(p, "lookup 2") || strstr(p, "lookup   2"))
1631                 return 0x2;
1632         if (strstr(p, "create d"))
1633                 return 0xd;
1634         if (strstr(p, "setattr 1"))
1635                 return 0x1;
1636         if (strstr(p, "setattr 2712")) /* 10002 NFS3ERR_NOT_SYNC */
1637                 return 0x2712;
1638         if (strstr(p, "lookup d"))
1639                 return 0xd;
1640         if (strstr(p, "read d"))
1641                 return 0xd;
1642         if (strstr(p, "write d"))
1643                 return 0xd;
1644         if (strstr(p, "write 46"))
1645                 return 0x46;
1646         if (strstr(p, "getattr 46"))
1647                 return 0x46;
1648         if (strstr(p, "mkdir d"))
1649                 return 0xd;
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");
1654 }
1655
1656 inline int find_reply_status_old (char * line)
1657 {
1658         char * p;
1659         int i=0;
1660
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 ");
1665                 if (p) {
1666                         p+=strlen(" 6 read ");
1667                 } else {
1668                         p = strstr (line, "status=XXX");
1669                         RFS_ASSERT (p);
1670                         p--;
1671                         RFS_ASSERT (*p==' ');
1672                         while (*p==' ')
1673                                 p--;
1674                         while (*p!=' ') {
1675                                 p--;
1676                         }
1677                         p++;
1678                 }
1679                 sscanf (p, "%x", &i);
1680                 if ((i<=0) || (i>10000))
1681                         printf("line %s\n", line);
1682                 RFS_ASSERT (i>0 && i<10009);
1683         }
1684         return i;
1685 }
1686
1687 inline char * find_reply_trace_fh (char * line)
1688 {
1689         char * p;
1690         p = strstr (line, "OK fh");
1691         if (!p) {
1692                 printf ("disk_index %d find_reply_trace_fh line %s\n", disk_index, line);
1693                 return NULL;
1694         } else
1695                 return p+6;
1696 }
1697
1698 #ifndef NO_DEPENDENCY_TABLE
1699 inline int disk_index_to_dep_index(int cur_dep_index, int disk_index)
1700 {
1701         int i;
1702         for (i=cur_dep_index; i>min_dep_index; i--) {
1703                 if (dep_tab[i].disk_index == disk_index)
1704                         return i;
1705         }
1706         RFS_ASSERT (0);
1707 }
1708 #endif
1709
1710 inline int is_play_candidate (int dep_index)
1711 {
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;
1715
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
1720          */
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 ++;
1726                 return FALSE;
1727         }
1728 #endif
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);
1735
1736                 failed_other_command_num ++;
1737                 return FALSE;
1738         }
1739 #endif
1740 #ifndef TAKE_CARE_SYMBOLIC_LINK
1741         if ((dep_tab[dep_index].proc==READLINK) ) { /* send request */
1742                 skipped_readlink_command_num ++;
1743                 return FALSE;
1744         }
1745 #endif
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.
1753          */
1754 /*
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"))
1757                 ) ||
1758                 (        ((dep_tab[dep_index].disk_index==238460) || (dep_tab[dep_index].disk_index ==238470))
1759                   && !(strcmp(trace_file, "anon-lair62-011130-1000.txt"))
1760                 )) {
1761                 skipped_custom_command_num++;
1762                 return FALSE;
1763         }
1764 */
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")))
1767                 ) ||
1768                 (        ((dep_tab[dep_index].disk_index==238460) || (dep_tab[dep_index].disk_index ==238470))
1769                   && !(strcmp(trace_file, "anon-lair62-011130-1000.txt"))
1770                 )) {
1771                 skipped_custom_command_num++;
1772                 return FALSE;
1773         }
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++;
1777                 return FALSE;
1778         }
1779 #endif
1780 #ifndef TAKE_CARE_FSSTAT_COMMAND
1781         /* the file handle used in this command is not processed properly by pre-processing */
1782         if (proc==FSSTAT) {
1783                 char * trace_fh = find_lead_trace_fh(proc, dep_tab[dep_index].line);
1784                 fh_map_t * fh = lookup_fh (trace_fh);
1785                 if (!fh) {
1786                         skipped_fsstat_command_num++;
1787                         return FALSE;
1788                 }
1789         }
1790 #endif
1791         return TRUE;
1792 }
1793
1794 inline int is_dir_op (int proc)
1795 {
1796         switch (proc) {
1797         case MKDIR:
1798         case CREATE:
1799         case LINK:
1800         case SYMLINK:
1801         case MKNOD:
1802         case REMOVE:
1803         case RMDIR:
1804         case RENAME:
1805                 return 1;
1806         default:
1807                 return 0;
1808         }
1809 }
1810
1811 inline int is_create_op (int proc)
1812 {
1813         if (proc==CREATE || proc==MKDIR || proc==LINK || proc==SYMLINK || proc==MKNOD || proc==RENAME)
1814                 return 1;
1815         return 0;
1816 }
1817
1818 inline int is_delete_op (int proc)
1819 {
1820         if (proc==REMOVE || proc==RMDIR || proc==RENAME)
1821                 return 1;
1822         return 0;
1823 }
1824
1825 static inline char * find_lead_trace_fh(int proc, char * line)
1826 {
1827         char * p;
1828         /* check the file handle availability */
1829         p = strstr (line, "fh");
1830         RFS_ASSERT (p);
1831         p+=3; //printf ("check dependency dep_tab[%d] trace_fh %s line %s \n", dep_index, trace_fh, line);
1832         return p;
1833 }
1834
1835 inline char * find_another_trace_fh(int proc, char * line)
1836 {
1837         char * p;
1838         /* check the file handle availability */
1839         p = strstr (line, "fh2");
1840         RFS_ASSERT (p);
1841         p+=4; //printf ("check dependency dep_tab[%d] trace_fh %s line %s \n", dep_index, trace_fh, line);
1842         return p;
1843 }
1844
1845 /* return the index of next request in dep_tab.
1846  * Return -1 if there is no suitable request to send
1847  */
1848 inline int get_nextop(void)
1849 {
1850         int i,j, k;
1851         int * t;
1852         static int dep_index = -2;
1853         char * line;
1854         char * p;
1855 #define INIT_MIN_WAIT_VALUE -999
1856         static int min_wait_fhandle_dep_index = INIT_MIN_WAIT_VALUE;
1857         int proc;
1858         int flag;
1859
1860         if (min_wait_fhandle_dep_index == -999)
1861                 min_wait_fhandle_dep_index = dep_window_index.head;
1862
1863         for (i=0; i<CYCLIC_NUM(dep_window_index); i++) {
1864                 dep_index = (dep_window_index.tail+i) % dep_window_index.size;
1865
1866                 proc = dep_tab[dep_index].proc;
1867                 flag = dep_tab[dep_index].flag;
1868
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;
1881                                 } else {
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;
1885                                 };
1886                                 dep_tab[dep_index].flag = DEP_FLAG_CANDIDATE;
1887 #ifdef TIME_PLAY
1888                                 dep_tab[dep_index].skip_sec = skip_sec;
1889 #endif
1890                                 if (dependency_debug)
1891                                         printf ("disk[%d] state DEP_FLAG_INIT to DEP_FLAG_CANDIDATE\n", dep_tab[dep_index].disk_index);
1892                         } else {
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;
1896                                 continue;
1897                         }
1898                 }
1899
1900                 if ((dep_tab[dep_index].flag == DEP_FLAG_CANDIDATE) || (dep_tab[dep_index].flag == DEP_FLAG_WAIT_FHANDLE) ) {
1901
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);
1906
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;
1918                                 } else {
1919                                         struct ladtime tmp;
1920                                         if (dep_index==dep_window_index.tail) {
1921                                                 if (!profile_debug)
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;
1925                                                 continue;
1926                                         }
1927                                         sfs_gettime (&tmp);
1928                                         SUBTIME (tmp, dep_tab[dep_index].start);
1929 #define DEPENDENCY_TIMEOUT 50
1930 #ifdef TIME_PLAY
1931                                         RFS_ASSERT (tmp.sec < DEPENDENCY_TIMEOUT + (skip_sec - dep_tab[dep_index].skip_sec));
1932 #else
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);
1937                                         }
1938                                         RFS_ASSERT (tmp.sec < DEPENDENCY_TIMEOUT );
1939 #endif
1940                                 }
1941                                 continue;
1942                         }
1943
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;
1951                                                         break;
1952                                                 }
1953                                         }
1954                                 }
1955                         }
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;
1959
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);
1964                                 return dep_index;
1965                         }
1966
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;
1974                                 continue;
1975                         }
1976                 }
1977
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);
1984                         }
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");
1988                                 continue;
1989                         }
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;
1993                         if (proc==RENAME)
1994                                 dep_tab[dep_index].fh_2->lock = 1;
1995
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);
2000                                 return dep_index;
2001                         }
2002
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;
2010                                 continue;
2011                         }
2012                         dep_tab[dep_index].flag = DEP_FLAG_DIRECTORY_READY;
2013                 }
2014
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);
2020                                 return dep_index;
2021                         }
2022                 }
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);
2028                                 j++, t++) {
2029                                 if (*t !=-1) {
2030                                         if (dep_tab[disk_index_to_dep_index(dep_index, *t)].flag == DEP_FLAG_DONE) {
2031                                                 /* The depended request has been finished */
2032                                                 *t = -1;
2033                                                 dep_tab[dep_index].cur_dep_num --;
2034                                         }
2035                                 }
2036                         }
2037
2038                         if (dep_tab[dep_index].cur_dep_num == 0) {
2039                                 return dep_index;
2040                         }
2041                 }
2042 #endif
2043         }
2044
2045         if (dependency_debug)
2046                 printf ("get_nexop return -1\n");
2047         return -1;
2048 }
2049
2050 int check_timeout(void)
2051 {
2052         static int biod_index = 0;
2053         int i;
2054         int dep_index;  /* index into dep_tab */
2055         int proc;
2056         sfs_op_type *op_ptr;            /* per operation info */
2057         struct ladtime timeout;
2058         struct ladtime current_time;
2059
2060         sfs_gettime (&current_time);
2061
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))) {
2067
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++;
2073
2074
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);
2079                                 } else {
2080                                         finish_request (biod_index, dep_index, NFS3ERR_RFS_TIMEOUT, DEP_FLAG_DONE);
2081                                 }
2082                                 timeout_num ++;
2083                                 num_out_reqs_statistics_at_timeout[num_out_reqs]++;
2084
2085                                 //RFS_ASSERT (!is_create_op(proc));
2086
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);
2089                         }
2090                 }
2091         }
2092 }
2093
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
2096  */
2097 struct biod_req * get_biod_req(int dep_index) /* index into dep_tab */
2098 {
2099         static int biod_index = 0;
2100         int i;
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;
2106                 num_out_reqs++;
2107                         return &(biod_reqp[biod_index]);
2108                 }
2109         }
2110         return NULL;
2111 }
2112
2113 /* Return index into biod_reqp
2114  * return -1 upon failure
2115  */
2116 int lookup_biod_req (int xid)
2117 {
2118         static int biod_index = 0;
2119         int i;
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)) {
2123                         return biod_index;
2124                 }
2125         }
2126         return -1;
2127 }
2128
2129 extern struct ladtime test_start;
2130 void init_time_offset(void)
2131 {
2132         struct ladtime tmp1;
2133         struct ladtime tmp2;
2134
2135         test_start.sec = 0;
2136         test_start.usec = 0;
2137         sfs_gettime (&tmp1);            /* called at initial time: tmp1 = play_starttime */
2138 #ifdef SPEED_UP
2139         DIVTIME (tmp1, PLAY_SCALE) /* tmp1 = play_starttime / SCALE */
2140 #endif
2141 #ifdef SLOW_DOWN
2142         MULTIME (tmp1, PLAY_SCALE) /* tmp1 = play_starttime * SCALE */
2143 #endif
2144
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 */
2148 }
2149
2150 /* initialize timestamp and proc field of dep_tab entry */
2151 void init_dep_tab_entry (int dep_index)
2152 {
2153         char * line;
2154         int version;
2155         int nfsproc;
2156         int msgid;
2157
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);
2166         } else {
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);
2171                         if (!line)
2172                                 line = get_line_by_disk_index (dep_tab[dep_index].disk_index-2);
2173                         RFS_ASSERT (line);
2174                         fprintf(stderr, "previousline %s\n", line);
2175                 }
2176                 RFS_ASSERT (line[TRACE_VERSION_POS] =='3');
2177                 if (nfsproc >= NFS3_PROCEDURE_COUNT) {
2178                         fprintf(stderr, "proc %d line %s\n", nfsproc, line);
2179
2180                 }
2181                 RFS_ASSERT (nfsproc <NFS3_PROCEDURE_COUNT);
2182                 dep_tab[dep_index].proc = nfs3proc_to_rfsproc[nfsproc];
2183         }
2184         RFS_ASSERT (dep_tab[dep_index].proc >= 0 && dep_tab[dep_index].proc < NOPS);
2185         dep_tab[dep_index].flag = DEP_FLAG_INIT;
2186 }
2187
2188 void adjust_play_window (int flag, int * poll_timeout_arg)
2189 {
2190         struct ladtime max_window_time;
2191         static struct ladtime max_poll_time = {0, 2000, 0};
2192         struct ladtime t;
2193         int i;
2194         char * line;
2195         cyclic_index_t old_dep_window_index = dep_window_index;
2196
2197 #ifdef notdef
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");
2204 #endif
2205
2206         while ((!CYCLIC_EMPTY(dep_window_index)) && (dep_tab[dep_window_index.tail].flag == DEP_FLAG_DONE)) {
2207 #ifdef notdef
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);
2213 #endif
2214                 CYCLIC_MOVE_TAIL(dep_tab_index);
2215                 CYCLIC_MOVE_TAIL(dep_window_index);
2216
2217 #ifdef notdef
2218                 CYCLIC_PRINT (dep_tab_index);
2219                 CYCLIC_PRINT (dep_window_index);
2220
2221                 if (! (dep_tab_index.tail == dep_window_index.tail)) {
2222                         CYCLIC_PRINT(dep_tab_index);
2223                         CYCLIC_PRINT(dep_window_index);
2224                 };
2225                 RFS_ASSERT ( dep_tab_index.tail == dep_window_index.tail);
2226 #endif
2227
2228                 if (!CYCLIC_EMPTY(dep_tab_index)) {
2229 #ifdef notdef
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);
2237                         }
2238                         RFS_ASSERT (CYCLIC_LESS (memory_trace_index, dep_tab[dep_tab_index.tail].memory_index, memory_trace_index.head));
2239 #endif
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);
2242                 } else {
2243                 //      CYCLIC_MOVE_TAIL (memory_trace_index);
2244                 }
2245         }
2246
2247         while (CYCLIC_EMPTY(dep_tab_index)) {
2248
2249                 if (disk_io_status == TRACE_FILE_END)
2250                         return;
2251                 else {
2252                         //printf ("************** ADJUST_PLAY_WINDOW sleep 1 s\n");
2253                         //print_cyclic_buffers();
2254                         //pthread_yield();
2255                         //usleep (1000);
2256                 }
2257         }
2258
2259         /* max_trace_window_time = current *|/ SCALE + trace_starttime */
2260         sfs_gettime (&current);
2261
2262 #ifdef TIME_PLAY
2263 #ifdef SPEED_UP
2264         MULTIME (current, PLAY_SCALE);
2265 #endif
2266 #ifdef SLOW_DOWN
2267         DIVTIME (current, PLAY_SCALE);
2268 #endif
2269         ADDTIME (current, trace_starttime);
2270         max_window_time = current;
2271
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);
2275                 //printf (".");
2276                 can_not_catch_speed_num ++;
2277         }
2278         while ((CYCLIC_NUM(dep_window_index) < MAX_PLAY_WINDOW) &&
2279                    (CYCLIC_NUM(dep_window_index) < CYCLIC_NUM(dep_tab_index)) ) {
2280                 struct ladtime t;
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))
2285             break;
2286                 CYCLIC_MOVE_HEAD(dep_window_index);
2287         }
2288 #else
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);
2294         }
2295 #endif
2296
2297         if (flag == BUSY)
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 */
2301         } else {
2302 #ifdef TIME_PLAY
2303                 struct ladtime tmp;
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);
2310
2311                 SUBTIME (tmp, max_window_time);
2312 #ifdef SPEED_UP
2313                 DIVTIME (tmp, PLAY_SCALE);
2314 #endif
2315 #ifdef SLOW_DOWN
2316                 MULTIME (tmp, PLAY_SCALE);
2317 #endif
2318 /*
2319                 tmp1 = tmp;
2320
2321                 if (tmp.sec > max_poll_time.sec) {
2322
2323                         if (rfs_debug)
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);
2328                         tmp.usec = 0;
2329                         skip_sec += tmp.sec;
2330                         SUBTIME (test_start, tmp);
2331                         tmp = max_poll_time;
2332                 }
2333 */
2334
2335                 //RFS_ASSERT ((tmp.sec < 1000));
2336                 if (tmp.sec > 1000)
2337                         tmp.sec = 1000;
2338                 if ((tmp.sec ==0) && (tmp.usec==0)) {
2339                         *poll_timeout_arg = 0;
2340                 } else
2341                         *poll_timeout_arg = tmp.sec*1000000+tmp.usec;
2342 #else
2343                 /*
2344                 struct ladtime tmp;
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;
2354                 */
2355
2356                 *poll_timeout_arg = 100000;
2357 #endif
2358         }
2359         if (rfs_debug)
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);
2363
2364 #ifdef notdef
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");
2371 #endif
2372         //CYCLIC_ASSERT(4);
2373 }
2374
2375 /* poll for usecs and receive, after receive one reply,
2376  * return index in biod_reqp of the corresponding request
2377  */
2378 int poll_and_get_reply (int usecs)
2379 {
2380         int biod_index = -1;
2381         int xid;
2382         int error;
2383         struct timeval zero_time = {0, 0}; /* Immediately return */
2384
2385 #ifdef RECV_THREAD
2386         //printf("recv thread waitsem 1\n");
2387         waitsem (async_rpc_sem);
2388         //printf("recv thread got sem 1\n");
2389 #endif
2390         do {
2391                 error = biod_poll_wait (NFS_client, usecs);
2392                 switch (error) {
2393                 case -1:
2394                         if (errno == EINTR) {
2395                                 error = 1;
2396                                 continue;
2397                         }
2398                         if (rfs_debug) {
2399                                 (void) fprintf(stderr, "biod_poll_wait error\n");
2400                                 perror ("");
2401                             (void) fflush(stderr);
2402                         }
2403                         break;
2404                 case 0:
2405                         break;
2406                 default:
2407 #ifdef UDP
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);
2417
2418                         biod_index = lookup_biod_req (xid);
2419                         sfs_gettime (&(biod_reqp[biod_index].stop));
2420 #else
2421                         RFS_ASSERT (0);
2422 #endif
2423                 }
2424         } while (0);
2425 #ifdef RECV_THREAD
2426         postsem (async_rpc_sem);
2427         //printf("recv thread postsem 1\n");
2428 #endif
2429         return biod_index;
2430 }
2431
2432 void print_result(void)
2433 {
2434         int i, j;
2435         struct ladtime t;
2436         int dep_index;
2437         int avg_msecs;
2438         unsigned long long tmp;
2439         int avg_usecs;
2440
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) {
2446                                 avg_msecs = 0;
2447                                 avg_usecs = 0;
2448                         } else {
2449                                 tmp = Ops[i].results.time.sec*1000000 + Ops[i].results.time.usec;
2450                                 avg_msecs = 0;
2451                                 avg_usecs = tmp/Ops[i].results.good_calls;
2452 /*
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;
2455 */
2456                         }
2457                         (void) fprintf(stdout,  "%11s\t%4.1f\t%4d\t%4d\t%4d\t\tsec %8d usec %8d \tusec %8d\n",
2458                                 Ops[i].name,
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);
2462                 }
2463                 (void) fflush (stdout);
2464     }
2465
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,
2478                         missing_reply_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,
2485                         read_io_err_num,
2486                         stale_fhandle_err_num,
2487                         abnormal_EEXIST_num,
2488                         abnormal_ENOENT_num,
2489                         proper_reply_num, run_stage_proper_reply_num);
2490 #endif
2491
2492 //  print_dump(Client_num, Child_num);
2493 }
2494
2495 /*
2496  * allocate and initialize client handles
2497  */
2498 static int
2499 init_rpc(void)
2500 {
2501         int dummy = 0;
2502
2503     /*
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().
2507      */
2508     if (DEBUG_CHILD_GENERAL) {
2509         (void) fprintf(stderr, "%s: set up client handle\n", sfs_Myname);
2510     }
2511
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]);
2516
2517     if (NFS_client  == ((CLIENT *) NULL)) {
2518         return(-1);
2519     }
2520
2521     /*
2522      * create credentials using the REAL uid
2523      */
2524     NFS_client->cl_auth = authunix_create(lad_hostname, (int)Real_uid,
2525                                       (int)Cur_gid, 0, NULL);
2526
2527         if (biod_init(dummy, dummy) == -1) {
2528                     return(-1);
2529         }
2530
2531     return(0);
2532 } /* init_rpc */
2533
2534 void
2535 init_counters(void)
2536 {
2537     uint_t i;
2538     uint_t start_msec;
2539
2540     /* Ready to go - initialize operation counters */
2541     for (i = 0; i < NOPS + 1; i++) {
2542         Ops[i].req_cnt = 0;
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;
2550     }
2551
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;
2561     Reqs_this_test = 0;
2562     Sleep_msec_this_test = 0;
2563 }
2564
2565 static char *
2566 nfs3_strerror(int status)
2567 {
2568     static char str[40];
2569     switch (status) {
2570         case NFS3_OK:
2571             (void) strcpy(str, "no error");
2572             break;
2573         case NFS3ERR_PERM:
2574             (void) strcpy(str, "Not owner");
2575             break;
2576         case NFS3ERR_NOENT:
2577             (void) strcpy(str, "No such file or directory");
2578             break;
2579         case NFS3ERR_IO:
2580             (void) strcpy(str, "I/O error");
2581             break;
2582         case NFS3ERR_NXIO:
2583             (void) strcpy(str, "No such device or address");
2584             break;
2585         case NFS3ERR_ACCES:
2586             (void) strcpy(str, "Permission denied");
2587             break;
2588         case NFS3ERR_EXIST:
2589             (void) strcpy(str, "File exists");
2590             break;
2591         case NFS3ERR_XDEV:
2592             (void) strcpy(str, "Cross-device link");
2593             break;
2594         case NFS3ERR_NODEV:
2595             (void) strcpy(str, "No such device");
2596             break;
2597         case NFS3ERR_NOTDIR:
2598             (void) strcpy(str, "Not a directory");
2599             break;
2600         case NFS3ERR_ISDIR:
2601             (void) strcpy(str, "Is a directory");
2602             break;
2603         case NFS3ERR_INVAL:
2604             (void) strcpy(str, "Invalid argument");
2605             break;
2606         case NFS3ERR_FBIG:
2607             (void) strcpy(str, "File too large");
2608             break;
2609         case NFS3ERR_NOSPC:
2610             (void) strcpy(str, "No space left on device");
2611             break;
2612         case NFS3ERR_ROFS:
2613             (void) strcpy(str, "Read-only file system");
2614             break;
2615         case NFS3ERR_MLINK:
2616             (void) strcpy(str, "Too many links");
2617             break;
2618         case NFS3ERR_NAMETOOLONG:
2619             (void) strcpy(str, "File name too long");
2620             break;
2621         case NFS3ERR_NOTEMPTY:
2622             (void) strcpy(str, "Directory not empty");
2623             break;
2624         case NFS3ERR_DQUOT:
2625             (void) strcpy(str, "Disc quota exceeded");
2626             break;
2627         case NFS3ERR_STALE:
2628             (void) strcpy(str, "Stale NFS file handle");
2629             break;
2630         case NFS3ERR_REMOTE:
2631             (void) strcpy(str, "Object is remote");
2632             break;
2633         case NFS3ERR_BADHANDLE:
2634             (void) strcpy(str, "Bad file handle");
2635             break;
2636         case NFS3ERR_NOT_SYNC:
2637             (void) strcpy(str, "Not sync write");
2638             break;
2639         case NFS3ERR_BAD_COOKIE:
2640             (void) strcpy(str, "Bad cookie");
2641             break;
2642         case NFS3ERR_NOTSUPP:
2643             (void) strcpy(str, "Operation not supported");
2644             break;
2645         case NFS3ERR_TOOSMALL:
2646             (void) strcpy(str, "Value too small");
2647             break;
2648         case NFS3ERR_SERVERFAULT:
2649             (void) strcpy(str, "Server fault");
2650             break;
2651         case NFS3ERR_BADTYPE:
2652             (void) strcpy(str, "Bad type");
2653             break;
2654         case NFS3ERR_JUKEBOX:
2655             (void) strcpy(str, "Jukebox");
2656             break;
2657         case NFS3ERR_RFS_TIMEOUT:
2658                 (void) strcpy(str, "Timeout");
2659                 break;
2660         default:
2661             (void) sprintf(str, "Unknown status %d", status);
2662             break;
2663     }
2664     return (str);
2665 }
2666
2667 /*
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
2671  * benchmark.
2672  */
2673 static void
2674 check_clock(void)
2675 {
2676         double time_res;
2677         char tmp_hostname[HOSTNAME_LEN];
2678
2679         time_res = get_resolution();
2680         getmyhostname(tmp_hostname, HOSTNAME_LEN);
2681         if( time_res > (double)SFS_MIN_RES )
2682         {
2683                 (void) fprintf(stderr,
2684                 "\n%s: Clock resolution too poor to obtain valid results.\n",
2685                         tmp_hostname);
2686                 (void) fprintf(stderr,
2687                 "%s: Clock resolution %f Micro seconds.\n", tmp_hostname,
2688                         time_res);
2689                 exit(175);
2690         }
2691         else
2692         {
2693                 (void) fprintf(stderr,
2694                 "\n%s: Good clock resolution [ %f ] Micro seconds.\n",
2695                         tmp_hostname, time_res);
2696         }
2697 }
2698
2699 /*
2700  * Lifted code from Iozone with permission from author. (Don Capps)
2701  * Returns the resolution of the gettimeofday() function
2702  * in microseconds.
2703  */
2704 static double
2705 get_resolution(void)
2706 {
2707         double starttime, finishtime, besttime;
2708         long  j,delay;
2709         int k;
2710
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 */
2714         for(k=0;k<10;k++)
2715         {
2716                 while(1)
2717                 {
2718                         starttime=time_so_far1();
2719                         for(j=0;j< delay;j++)
2720                         ;
2721                         finishtime=time_so_far1();
2722                         if(starttime==finishtime)
2723                                 delay++;
2724                         else
2725                         {
2726                                 if(k==0)
2727                                         besttime=(finishtime-starttime);
2728                                 if((finishtime-starttime) < besttime)
2729                                         besttime=(finishtime-starttime);
2730                                 break;
2731                         }
2732                 }
2733         }
2734          return(besttime);
2735 }
2736
2737 /*
2738  * Lifted code from Iozone with permission from author. (Don Capps)
2739  * Returns current result of gettimeofday() in microseconds.
2740  */
2741 /************************************************************************/
2742 /* Time measurement routines.                                           */
2743 /* Return time in microseconds                                          */
2744 /************************************************************************/
2745
2746 static double
2747 time_so_far1(void)
2748 {
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 */
2753         /* resolution.  */
2754 #ifdef Windows
2755         LARGE_INTEGER freq,counter;
2756         double wintime;
2757         double bigcounter;
2758
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);
2765 #else
2766 #if defined (OSFV4) || defined(OSFV3) || defined(OSFV5)
2767   struct timespec gp;
2768
2769   if (getclock(TIMEOFDAY, (struct timespec *) &gp) == -1)
2770     perror("getclock");
2771   return (( (double) (gp.tv_sec)*1000000.0) +
2772     ( ((float)(gp.tv_nsec)) * 0.001 ));
2773 #else
2774   struct timeval tp;
2775
2776   if (gettimeofday(&tp, (struct timezone *) NULL) == -1)
2777     perror("gettimeofday");
2778   return ((double) (tp.tv_sec)*1000000.0) +
2779     (((double) tp.tv_usec) );
2780 #endif
2781 #endif
2782 }
2783
2784 static void
2785 usage(void)
2786 {
2787         fprintf(stderr, "trace play usage");
2788 }
2789 extern void init_file_system (void)
2790 {
2791         return;
2792 }
2793
2794 void show_fhandle (nfs_fh3 * fhp)
2795 {
2796         struct knfs_fh * kfhp = (struct knfs_fh *)fhp;
2797
2798         int dev;
2799
2800         if (quiet_flag)
2801                 return;
2802
2803         RFS_ASSERT (kfhp->fh_version == 1);
2804         RFS_ASSERT (kfhp->fh_fsid_type == 0);
2805         RFS_ASSERT (kfhp->fh_auth_type == 0);
2806
2807         dev = ntohs(kfhp->fh_dev_major);
2808         dev = dev<<8;
2809         dev = dev + ntohs(kfhp->fh_dev_minor);
2810
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
2814          */
2815
2816         switch (kfhp->fh_fileid_type) {
2817                 case 0:
2818                         printf("fh:type 0 root dev 0x%x dev_ino %d\n", dev, kfhp->fh_dev_ino);
2819                         break;
2820                 case 1:
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);
2823                         break;
2824                 case 2:
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);
2827                         break;
2828                 default:
2829                         RFS_ASSERT (0);
2830         }
2831 }
2832
2833 nfs_fh3 zero_fhandle;
2834 int init_fh_map ()
2835 {
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);
2840         fh_i = 0;
2841 }
2842
2843 int add_fh (int map_flag, char * trace_fh, char * path, nfs_fh3 * play_fh)
2844 {
2845         char * old_trace_fh;
2846
2847         /* first lookup if the entry for fh is already in the table */
2848     struct generic_entry * p;
2849
2850     p = generic_lookup (trace_fh, TRACE_FH_SIZE, 0, fh_htable, FH_HTABLE_SIZE);
2851         if (p) {
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)) {
2857                         int i;
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));
2866 #else
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));
2870                         }
2871 #endif
2872                         RFS_ASSERT (0);
2873                 }
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
2878                  */
2879 #ifdef TAKE_CARE_SYMBOLIC_LINK
2880                 RFS_ASSERT (!memcmp(&fh_map[p->key3].play_fh, &zero_fhandle, sizeof(nfs_fh3)));
2881 #endif
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);
2885                 return 0;
2886         }
2887
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);
2891
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));
2896         else
2897                 memset (&fh_map[fh_i].play_fh, 0, sizeof(nfs_fh3));
2898
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);
2903                 } else
2904                         printf("null\n");
2905         }
2906
2907 /*
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);
2910 */
2911
2912     generic_insert(trace_fh, TRACE_FH_SIZE, fh_i, fh_htable, FH_HTABLE_SIZE);
2913
2914         fh_i = (fh_i+1);
2915         RFS_ASSERT (fh_i < FH_MAP_SIZE);
2916
2917     return 0;
2918 };
2919
2920 inline fh_map_t * lookup_fh (char * trace_fh )
2921 {
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);
2926
2927     if (p) {
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);
2931                 }
2932                 RFS_ASSERT (!memcmp(fh_map[p->key3].trace_fh, trace_fh, TRACE_FH_SIZE));
2933         return (&(fh_map[p->key3]));
2934     } else {
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);
2938                 }
2939         return NULL;
2940         }
2941         RFS_ASSERT (0);
2942 }
2943
2944 int delete_fh (char * trace_fh, int fh_map_index)
2945 {
2946     generic_delete (trace_fh, TRACE_FH_SIZE, fh_map_index, fh_htable, FH_HTABLE_SIZE);
2947     return 0;
2948 };
2949
2950 int lookup_init_filesystem (nfs_fh3 * parent, char * name, nfs_fh3 * result)
2951 {
2952     LOOKUP3args         args;
2953     LOOKUP3res          reply;          /* the reply */
2954     enum clnt_stat      rpc_stat;       /* result from RPC call */
2955     struct ladtime      start;
2956     struct ladtime      stop;
2957         static int i=0;
2958
2959     /* set up the arguments */
2960     (void) memcpy((char *) &args.what.dir, (char *) parent,
2961                                                         sizeof (nfs_fh3));
2962     args.what.name = name;
2963     (void) memset((char *) &reply.resok.object, '\0', sizeof (nfs_fh3));
2964
2965     /* make the call */
2966     sfs_gettime(&start);
2967     rpc_stat = clnt_call(NFS_client, NFSPROC3_LOOKUP,
2968                         xdr_LOOKUP3args, (char *) &args,
2969                         xdr_LOOKUP3res, (char *) &reply,
2970                         Nfs_timers[Init]);
2971     sfs_gettime(&stop);
2972
2973         if (rpc_stat !=RPC_SUCCESS) {
2974                 printf("rpc_stat %d\n", rpc_stat);
2975                 perror("");
2976         }
2977     RFS_ASSERT (rpc_stat == RPC_SUCCESS);
2978         (void) memcpy((char *) result, (char *) &reply.resok.object, sizeof (nfs_fh3));
2979         return (reply.status);
2980 }
2981
2982 void read_fh_map(char * fh_map_file)
2983 {
2984         FILE * fp;
2985         int i = 0;
2986         char buf[1024];
2987         char trace_fh[MAX_TRACE_FH_SIZE];
2988         char intbuf[9];
2989         char * trace_path;
2990         char * p;
2991         int map_flag;
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];
2996         int depth;
2997         int new_dir_flag = 0;
2998         int lineno = 0;
2999
3000         depth = 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];
3005
3006         fp = fopen(fh_map_file, "r");
3007         if (!fp) {
3008                 printf ("can not opern %s\n", fh_map_file);
3009                 perror("open");
3010                 exit (0);
3011         }
3012         RFS_ASSERT (fp!=NULL);
3013         if (strstr(fh_map_file, "fmt1")) {
3014                 TRACE_FH_SIZE = 48;
3015         }
3016
3017         intbuf[8]=0;
3018
3019         memset(buf, 0, sizeof(buf));
3020         while (fgets(buf, 1024, fp)) {
3021                 lineno ++;
3022                 if (fh_i % 10000==0)
3023                         printf("%d fh_map entry read\n", fh_i);
3024
3025                 RFS_ASSERT (buf[strlen(buf)-1]=='\n');
3026                 buf[strlen(buf)-1]=0;
3027                 if (fh_map_debug) {
3028                         printf("%d fgets return %s\n", fh_i, buf);
3029                         printf("depth %d lookup_path %s\n", depth, lookup_path);
3030                 }
3031                 //for (i=0; i<=depth; i++)
3032                         //printf("lookup_path_ptr[%d] %s ", i, lookup_path_ptr[i]);
3033                 //printf("\n");
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
3038                 }
3039                 trace_path = buf+TRACE_FH_SIZE*2+1;             /* +1 the trace contains only initial file handle */
3040 #else
3041                 memcpy(trace_fh, buf, TRACE_FH_SIZE);
3042                 trace_path = buf + TRACE_FH_SIZE +1;
3043 #endif
3044 #ifdef TRACE_CONTAIN_LATER_FHANDLE
3045                 trace_path = +=2;       /* +3 if the trace contains both initial and later created file handle */
3046 #endif
3047
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);
3053                         continue;
3054                 }
3055 #endif
3056
3057                 p = trace_path+strlen(trace_path)-2;
3058                 while (*p!='/')
3059                         p--;
3060                 p++;
3061                 //RFS_ASSERT (p-trace_path<=strlen(lookup_path)+1);
3062                 //RFS_ASSERT (p>trace_path);
3063
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);
3066                 }
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");
3071                         if (depth<=0)
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;
3076                         depth--;
3077                 }
3078                 RFS_ASSERT (strlen(lookup_path)==(p-trace_path) || (depth==0));
3079
3080
3081 #ifdef TRACE_CONTAIN_LATER_FHANDLE
3082                 if (buf[TRACE_FH_SIZE*2+1]=='Y') {
3083                         map_flag = FH_MAP_FLAG_COMPLETE;
3084                 } else {
3085                         map_flag = FH_MAP_FLAG_PARTIAL;
3086                         RFS_ASSERT (buf[TRACE_FH_SIZE*2+1]=='N');
3087                 }
3088 #else
3089                 map_flag = FH_MAP_FLAG_COMPLETE;
3090 #endif
3091                 if ((*(p+strlen(p)-1))=='/') {
3092                         *(p+strlen(p)-1)=0;
3093                         new_dir_flag = 1;
3094                 } else
3095                         new_dir_flag = 0;
3096
3097                 if (map_flag == FH_MAP_FLAG_COMPLETE) {
3098                         int ret = lookup_init_filesystem (&parents[depth], p, &parents[depth+1]);
3099                         if (ret!=NFS3_OK) {
3100                                 printf ("lineno %d %s\n", lineno, buf);
3101                         }
3102                         RFS_ASSERT (ret == NFS3_OK);
3103                         add_fh (map_flag, buf, trace_path, &parents[depth+1]);
3104                 } else
3105                         add_fh (map_flag, buf, trace_path, 0);
3106
3107                 if (new_dir_flag) {
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, "/");
3112
3113                         //printf("depth++\n");
3114                         depth++;
3115                 }
3116
3117                 memset(buf, 0, sizeof(buf));
3118         }
3119
3120         if (fh_map_debug) {
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));
3128 #else
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));
3132                 }
3133 #endif
3134
3135                 fprintf(stderr, "total %d requests \n", i);
3136         }
3137 }
3138
3139 int f()
3140 {
3141         return 1;
3142 }
3143
3144 inline free_biod_req (int biod_index)
3145 {
3146         RFS_ASSERT (biod_reqp[biod_index].in_use == TRUE);
3147         biod_reqp[biod_index].in_use = FALSE;
3148         num_out_reqs --;
3149 }
3150
3151 void finish_request (int biod_index, int dep_index, int status, int dep_flag)
3152 {
3153         static int i = 0;
3154         /* the ending operation, same as when a request time out */
3155
3156         dep_tab[dep_index].stop = biod_reqp[biod_index].stop;   /* RFS: to dump data */
3157         free_biod_req (biod_index);
3158
3159         dep_tab[dep_index].status = status;
3160
3161         if (event_order_index < EVENT_ORDER_SIZE)
3162                 event_order[event_order_index++] = -dep_tab[dep_index].disk_index;
3163
3164         dep_tab[dep_index].flag = dep_flag;
3165         if (is_dir_op(dep_tab[dep_index].proc)) {
3166                 int j;
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);
3176                 }
3177         }
3178 }
3179
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];
3185
3186 int execute_next_request ()
3187 {
3188         int dep_index;
3189         int proc;
3190         char * line;
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;
3195
3196         if (num_out_reqs == max_biod_reqs) {
3197                 return -1;
3198         }
3199
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);
3205                 return dep_index;
3206         };
3207         end_profile (&valid_get_nextop_profile);
3208
3209         start_profile (&prepare_argument_profile);
3210         line = dep_tab[dep_index].line;
3211
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);
3214
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);
3219 /*
3220                 CYCLIC_PRINT (dep_tab_index);
3221                 {
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);
3225                 }
3226 */
3227 #ifdef TIME_PLAY
3228 #ifdef SPEED_UP
3229 /*
3230                 if (can_not_catch_speed_num < 2000) {
3231                         PLAY_SCALE ++;
3232                         printf ("set PLAY_SCALE to %d\n", PLAY_SCALE);
3233                 };
3234                 if (can_not_catch_speed_num > 50000) {
3235                         PLAY_SCALE /= 2;
3236                 } else {
3237                         if (can_not_catch_speed_num > 5000) {
3238                                 PLAY_SCALE -= 2;
3239                                 if (PLAY_SCALE < 1)
3240                                         PLAY_SCALE = 1;
3241                         }
3242                 }
3243 */
3244 #endif
3245                 if ((total_profile.in.tv_sec > 100)) {
3246                         can_not_catch_speed_num_total += can_not_catch_speed_num;
3247                 }
3248                 can_not_catch_speed_num = 0;
3249 #endif
3250         }
3251         if (rfs_debug)
3252                 printf ("processing dep_tab[%d] disk_index %d %s\n", dep_index, dep_tab[dep_index].disk_index, line);
3253
3254         proc = dep_tab[dep_index].proc;
3255         rfs_Ops[proc].setarg (dep_index, line, arg_res, buf1, buf2);
3256
3257         op_ptr = &Ops[proc];
3258         reqp = get_biod_req (dep_index);
3259         RFS_ASSERT (reqp);
3260
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;
3264 #else
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;
3272 #endif
3273
3274     /* make the call */
3275     sfs_gettime(&(reqp->start));
3276         end_profile (&prepare_argument_profile);
3277         start_profile (&biod_clnt_call_profile);
3278 #define REAL_PLAY
3279 #ifdef REAL_PLAY
3280
3281 #ifdef RECV_THREAD
3282         //printf ("send thread waitsem\n");
3283         waitsem(async_rpc_sem);
3284         //printf ("send thread got sem\n");
3285 #endif
3286     reqp->xid = biod_clnt_call(NFS_client, rfs_Ops[proc].nfsv3_proc,
3287                                         rfs_Ops[proc].xdr_arg, arg_res);
3288 #ifdef RECV_THREAD
3289         postsem(async_rpc_sem);
3290         //printf ("send thread postsem\n");
3291 #endif
3292
3293 #else   // REAL_PLAY
3294         reqp->xid = dep_index+1;        /* just fake a message id and let it expire */
3295 #endif
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;
3302
3303         dep_tab[dep_index].start = reqp->start; /* RFS: to dump data */
3304         end_profile (&biod_clnt_call_profile);
3305
3306         send_num ++;
3307 }
3308
3309 void check_reply (int proc, int biod_index, int dep_index, int status, char * errmsg, int trace_status)
3310 {
3311         if (((status!=trace_status)) && (status!=NFS3_OK) && (trace_status!=NFS3ERR_RFS_MISS)) {
3312                 if (!profile_debug)
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
3317                  */
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
3321                          * rename occurs
3322                          */
3323                         rename_rmdir_noent_reply_num++;
3324                 } else
3325 #endif
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
3331                          */
3332                         RFS_ASSERT (1);
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
3337                          * file already
3338                          */
3339                         RFS_ASSERT (1);
3340                 } else
3341 #endif
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)) {
3345                         RENAME3args             args;
3346                         RENAME3res              reply;          /* the reply */
3347                         RMDIR3args * rmdir_argp;
3348                         enum clnt_stat rpc_stat;        /* result from RPC call */
3349
3350                         rfs_Ops[proc].setarg (dep_index, dep_tab[dep_index].line, arg_res, buf1, buf2);
3351                         rmdir_argp = (RMDIR3args *)arg_res;
3352
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);
3358
3359                         rpc_stat = clnt_call(NFS_client, NFSPROC3_RENAME,
3360                         xdr_RENAME3args, (char *) &args,
3361                         xdr_RENAME3res, (char *) &reply,
3362                                 Nfs_timers[Init]);
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 ++;
3368 #endif
3369 #ifndef TAKE_CARE_ACCESS_ERROR
3370                 } else if ((status==0) && (trace_status==NFS3ERR_ACCES)) {
3371                         loose_access_control_reply_num ++;
3372 #endif
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
3379                          */
3380                         lookup_err_due_to_parallel_remove_num ++;
3381 #endif
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
3385                  * could be ENOENT
3386                  */
3387                 } else if ((proc==LOOKUP) && (status==NFS3ERR_NOENT) && (trace_status==NFS3ERR_ACCES)) {
3388                         lookup_eaccess_enoent_mismatch_num ++;
3389 #endif
3390 #ifdef TOLERANT_READ_IO_ERR
3391                 } else if ((proc==READ) && (status==NFS3ERR_IO) && (trace_status==NFS3_OK)) {
3392                         read_io_err_num ++;
3393 #endif
3394 #ifdef TOLERANT_STALE_FHANDLE_ERR
3395                 } else if ((status==NFS3ERR_STALE) && (trace_status==NFS3_OK)) {
3396                         printf ("!!!!!!! STALE FILE HANDLE \n");
3397                         //sleep(1);
3398                         stale_fhandle_err_num ++;
3399 #endif
3400                 } else {
3401                         int i;
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);
3405                         }
3406
3407                         if (status==EEXIST) {
3408                                 abnormal_EEXIST_num ++;
3409                         } else if (status == ENOENT) {
3410                                 abnormal_ENOENT_num ++;
3411                         } else {
3412                                 printf ("!!!!!!!!!!!!!1 should fail\n");
3413                                 //RFS_ASSERT (0);
3414                         }
3415                 }
3416         } else {
3417                 proper_reply_num ++;
3418                 if (total_profile.in.tv_sec >= WARMUP_TIME)
3419                         run_stage_proper_reply_num ++;
3420         }
3421
3422 }
3423
3424 /* return -1 if there is no reply being received
3425  * return the dep_index if the corresponding reply has been received
3426  */
3427 int receive_next_reply (int busy_flag)
3428 {
3429         int dep_index;
3430         int biod_index;
3431         int proc;
3432         char * line;
3433         char * reply_line;
3434         sfs_op_type *op_ptr;            /* per operation info */
3435         int ret;
3436         int status;
3437         int trace_status;
3438         char * errmsg;
3439         int poll_timeout = 0;           /* timeout in usecs */
3440
3441         /* wait for reply */
3442         start_profile (&valid_poll_and_get_reply_profile);
3443         start_profile (&invalid_poll_and_get_reply_profile);
3444
3445         if (busy_flag == BUSY) {
3446                 poll_timeout = 0;
3447                 poll_timeout_0_num ++;
3448         } else {
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 ++;
3452         }
3453
3454         biod_index = poll_and_get_reply (poll_timeout);
3455         if (biod_index==-1) {
3456                 end_profile (&invalid_poll_and_get_reply_profile);
3457                 return -1;
3458         };
3459         end_profile (&valid_poll_and_get_reply_profile);
3460
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);
3466         } else {
3467                 printf ("biod_index %d reply received but the request has been time out\n", biod_index);
3468                 return -1;
3469         }
3470
3471         proc = dep_tab[dep_index].proc;
3472         op_ptr = &Ops[proc];
3473
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);
3480                 return dep_index;
3481         }
3482         RFS_ASSERT (dep_tab[dep_index].flag == DEP_FLAG_SENT);
3483
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);
3491
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;
3497
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);
3500
3501         /* error checking */
3502         check_reply (proc, biod_index, dep_index, status, errmsg, trace_status);
3503
3504         /* free resources */
3505         finish_request (biod_index, dep_index, status, DEP_FLAG_DONE);
3506         recv_num ++;
3507
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++;
3514         } else {
3515                 op_ptr->results.bad_calls++;
3516                 Ops[TOTAL].results.bad_calls++;
3517         }
3518         sfs_elapsedtime (op_ptr, &(biod_reqp[biod_index].start), &(biod_reqp[biod_index].stop));
3519         end_profile (&check_reply_profile);
3520         }
3521
3522         //start_profile (&add_create_object_profile);
3523
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);
3527 #endif
3528                 if (status!=NFS3_OK) {
3529                         /* commented out for 1022 */
3530                         printf ("!!!!!! Should have been an ASSERTION FAILURE \n");
3531                         RFS_ASSERT (proc==SYMLINK);
3532                         RFS_ASSERT (0);
3533                 } else {
3534                         if (proc!=SYMLINK || line[TRACE_VERSION_POS]!='2')
3535                                 add_new_file_system_object(proc, dep_index, line, reply_line);
3536                 }
3537         }
3538         //end_profile (&add_create_object_profile);
3539 }
3540
3541 inline void add_new_file_system_object (int proc, int dep_index, char * line, char * reply_line)
3542 {
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;
3551
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);
3561
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;
3566 #else
3567         reply_trace_fh = find_reply_trace_fh (reply_line);
3568 #endif
3569         RFS_ASSERT (reply_trace_fh != NULL);
3570         switch (proc) {
3571         case CREATE:
3572                 RFS_ASSERT (((CREATE3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3573                 child_fh3 = &((CREATE3res *)arg_res)->res_u.ok.obj.handle;
3574                 break;
3575         case MKDIR:
3576                 RFS_ASSERT (((MKDIR3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3577                 child_fh3 = &((MKDIR3res *)arg_res)->res_u.ok.obj.handle;
3578                 break;
3579         case SYMLINK:
3580                 RFS_ASSERT (((SYMLINK3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3581                 child_fh3 = &((SYMLINK3res *)arg_res)->res_u.ok.obj.handle;
3582                 break;
3583         case MKNOD:
3584                 RFS_ASSERT (((MKNOD3res *)arg_res)->res_u.ok.obj.handle_follows==TRUE);
3585                 child_fh3 = &((MKNOD3res *)arg_res)->res_u.ok.obj.handle;
3586                 break;
3587         case LOOKUP:
3588                 RFS_ASSERT (proc==LOOKUP);
3589                 child_fh3 = &((LOOKUP3res *)arg_res)->res_u.ok.object;
3590                 break;
3591         default:
3592                 RFS_ASSERT (0);
3593         }
3594 #ifndef REDUCE_MEMORY_TRACE_SIZE
3595         RFS_ASSERT (reply_trace_fh[TRACE_FH_SIZE]==' ');
3596 #endif
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] = ' ';
3602 #endif
3603 }
3604
3605 /* initialize timestamp and proc field of dep_tab entry */
3606 void trace_play(void)
3607 {
3608
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.
3614          */
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;
3620
3621 #ifndef IO_THREAD
3622         disk_io_status = read_trace();
3623 #endif
3624
3625         RFS_ASSERT (!CYCLIC_EMPTY(dep_tab_index));
3626         CYCLIC_MOVE_HEAD(dep_window_index);
3627
3628         adjust_play_window(busy_flag, &poll_timeout);
3629
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)) {
3634                         int i;
3635
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;
3642                                 }
3643                         }
3644                         printf("\n");
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;
3649                                 }
3650                         }
3651                         printf("\n");
3652                         //      CYCLIC_PRINT(dep_tab_index);
3653                 }
3654
3655                 if ((total_profile.in.tv_sec > 6000)) {
3656                         printf ("the process has run for more than 600 seconds, exit\n");
3657                         goto END;
3658                 }
3659
3660                 if (busy_flag == IDLE) {
3661 #ifndef RECV_THREAD
3662                         //start_profile (&check_timeout_profile);
3663                         check_timeout();
3664                         //end_profile (&check_timeout_profile);
3665 #endif
3666 #ifndef IO_THREAD
3667                         if (disk_io_status!=TRACE_FILE_END) {
3668                                 disk_io_status = read_trace();
3669                         };
3670 #endif
3671                 }
3672
3673                 //start_profile (&adjust_play_window_profile);
3674                 adjust_play_window (busy_flag, &poll_timeout);
3675                 if (rfs_debug)
3676                         printf("num_out_reqs %d\n", num_out_reqs);
3677                 num_out_reqs_statistics[num_out_reqs]++;
3678                 busy_flag = IDLE;
3679                 //end_profile (&adjust_play_window_profile);
3680
3681                 start_profile (&execute_next_request_profile);
3682                 while (execute_next_request()!=-1) {
3683                         busy_flag = BUSY;
3684                 }
3685                 end_profile (&execute_next_request_profile);
3686
3687 #ifndef RECV_THREAD
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
3692
3693 #ifdef SEND_HIGHER_PRIORITY_POLICY
3694                 receive_next_reply(IDLE);
3695 #endif
3696 #ifdef SEND_RECEIVE_EQUAL_PRIORITY_POLICY
3697                 busy_flag = IDLE;
3698                 while (receive_next_reply(busy_flag)!=-1)
3699                         busy_flag = BUSY;
3700 #endif
3701                 end_profile (&receive_next_reply_profile);
3702 #endif
3703                 CYCLIC_ASSERT (0);
3704         }
3705         end_profile (&total_profile);
3706
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);
3711         }
3712         RFS_ASSERT(num_out_reqs==0);
3713
3714 END:
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);
3721         printf("\n");
3722         //print_profile ("check_timeout", &check_timeout_profile);
3723         //printf("\n");
3724         //print_profile ("adjust_play_window", &adjust_play_window_profile);
3725         //printf("\n");
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);
3731         printf("\n");
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);
3741         printf("\n");
3742
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);
3744 }
3745
3746
3747 int CYCLIC_SET_TAIL_TO(cyclic_index_t * index, int dest)
3748 {
3749         cyclic_index_t indextmp, indextmp2;
3750         int oldnum, num;
3751         indextmp = *index;
3752         indextmp2 = indextmp;
3753         oldnum = CYCLIC_NUM(indextmp);
3754
3755         if (! ((dest>=0) && (dest<indextmp.size))) {
3756                 CYCLIC_PRINT(indextmp);
3757                 printf("dest %d\n", dest);
3758         }
3759         RFS_ASSERT ((dest>=0) && (dest<indextmp.size));
3760         index->tail = dest;
3761         indextmp2.tail = dest;
3762         num = CYCLIC_NUM(indextmp2);
3763
3764         if (num > oldnum) {
3765                 CYCLIC_PRINT(indextmp);
3766                 CYCLIC_PRINT(indextmp2);
3767                 printf("dest %d old_num %d num %d\n", dest, oldnum, num);
3768         }
3769         RFS_ASSERT (num <= oldnum);
3770 }
3771
3772 int flush_junk()
3773 {
3774         int i;
3775         for (i=0; i<500; i++) {
3776                 printf ("*************************************************************\n");
3777         }
3778         fflush(stdout);
3779 }
3780
3781 int CYCLIC_ASSERT (int i)
3782 {
3783         int j;
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);
3788                 flush_junk();
3789                 sleep (10);
3790                 RFS_ASSERT (0);
3791         };
3792
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);
3798                 flush_junk();
3799                 sleep (10);
3800                 RFS_ASSERT (0);
3801         };
3802         for (i=0, j=0; i<max_biod_reqs; i++) {
3803                 if (biod_reqp[i].in_use == 1)
3804                         j++;
3805         }
3806 #ifndef RECV_THREAD
3807         RFS_ASSERT (num_out_reqs==j);
3808 #endif
3809 /*
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 ));
3812 */
3813 }
3814
3815 /* sfs_c_chd.c */