From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from 173-166-109-252-newengland.hfc.comcastbusiness.net ([173.166.109.252]:33454 "EHLO bombadil.infradead.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752872Ab3BRN7Z (ORCPT ); Mon, 18 Feb 2013 08:59:25 -0500 Date: Mon, 18 Feb 2013 14:57:56 +0100 From: Jens Axboe Subject: Re: All I/O patterns are replayed to one file with fio 2.0.13 Message-ID: <20130218135756.GQ6003@kernel.dk> References: <511D3CDE.6070302@informatik.uni-rostock.de> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <511D3CDE.6070302@informatik.uni-rostock.de> Sender: fio-owner@vger.kernel.org List-Id: fio@vger.kernel.org To: Nikolaus Jeremic Cc: fio@vger.kernel.org On Thu, Feb 14 2013, Nikolaus Jeremic wrote: > Hi, > > I've tried to replay I/Os from a textual iolog file to a couple of files > using fio 2.0.13 on Linux. However, all I/Os were performed to the last > opened file, which is '/mnt/ssd5/rand-write.1.0_1_2' in this example . My > jobfile and iolog files contain the following: > > ############### job file ######### > [global] > name=replay_filetraces > description=Replay file traces > ioengine=libaio > iodepth=6 > direct=1 > continue_on_error=1 > > [replay] > numjobs=1 > read_iolog=file_io_patterns > unlink=0 > ############## EOF ######### > > > ############## iolog file ######### > fio version 2 iolog > /mnt/ssd0/rand-write.1.0_0_0 add > /mnt/ssd1/rand-write.1.0_0_1 add > /mnt/ssd2/rand-write.1.0_0_2 add > /mnt/ssd3/rand-write.1.0_1_0 add > /mnt/ssd4/rand-write.1.0_1_1 add > /mnt/ssd5/rand-write.1.0_1_2 add > /mnt/ssd0/rand-write.1.0_0_0 open > /mnt/ssd1/rand-write.1.0_0_1 open > /mnt/ssd2/rand-write.1.0_0_2 open > /mnt/ssd3/rand-write.1.0_1_0 open > /mnt/ssd4/rand-write.1.0_1_1 open > /mnt/ssd5/rand-write.1.0_1_2 open > /mnt/ssd0/rand-write.1.0_0_0 write 0 65536 > /mnt/ssd1/rand-write.1.0_0_1 write 0 65536 > /mnt/ssd2/rand-write.1.0_0_2 write 0 65536 > /mnt/ssd3/rand-write.1.0_1_0 write 0 65536 > /mnt/ssd4/rand-write.1.0_1_1 write 0 65536 > /mnt/ssd5/rand-write.1.0_1_2 write 0 65536 > /mnt/ssd0/rand-write.1.0_0_0 write 65536 65536 > /mnt/ssd1/rand-write.1.0_0_1 write 65536 65536 > /mnt/ssd2/rand-write.1.0_0_2 write 65536 65536 > /mnt/ssd3/rand-write.1.0_1_0 write 65536 65536 > /mnt/ssd4/rand-write.1.0_1_1 write 65536 65536 > /mnt/ssd5/rand-write.1.0_1_2 write 65536 65536 > /mnt/ssd0/rand-write.1.0_0_0 close > /mnt/ssd1/rand-write.1.0_0_1 close > /mnt/ssd2/rand-write.1.0_0_2 close > /mnt/ssd3/rand-write.1.0_1_0 close > /mnt/ssd4/rand-write.1.0_1_1 close > /mnt/ssd5/rand-write.1.0_1_2 close > ############## EOF ######### > > I've turned on debugging and added some extra printf in read_iolog2() within > iolog.c. > > ############## begin of debug excerpt ######## > file 24594 add file /mnt/ssd0/rand-write.1.0_0_0 > file 24594 resize file array to 2 files > file 24594 file 0x7fbe03f53090 "/mnt/ssd0/rand-write.1.0_0_0" added at 0 > file 24594 add file /mnt/ssd1/rand-write.1.0_0_1 > file 24594 file 0x7fbe03f53230 "/mnt/ssd1/rand-write.1.0_0_1" added at 1 > file 24594 add file /mnt/ssd2/rand-write.1.0_0_2 > file 24594 resize file array to 4 files > file 24594 file 0x7fbe03f533d0 "/mnt/ssd2/rand-write.1.0_0_2" added at 2 > file 24594 add file /mnt/ssd3/rand-write.1.0_1_0 > file 24594 file 0x7fbe03f53570 "/mnt/ssd3/rand-write.1.0_1_0" added at 3 > file 24594 add file /mnt/ssd4/rand-write.1.0_1_1 > file 24594 resize file array to 6 files > file 24594 file 0x7fbe03f53710 "/mnt/ssd4/rand-write.1.0_1_1" added at 4 > file 24594 add file /mnt/ssd5/rand-write.1.0_1_2 > file 24594 file 0x7fbe03f538b0 "/mnt/ssd5/rand-write.1.0_1_2" added at 5 > io 24594 read_iolog2: Making note of file. offset=7310584035475809390 > bytes=811544671 fileno=0 file_action=1 fname=/mnt/ssd0/rand-write.1.0_0_0 > act=open > io 24594 read_iolog2: Making note of file. offset=7310584035475809390 > bytes=811544671 fileno=1 file_action=1 fname=/mnt/ssd1/rand-write.1.0_0_1 > act=open > io 24594 read_iolog2: Making note of file. offset=7310584035475809390 > bytes=811544671 fileno=2 file_action=1 fname=/mnt/ssd2/rand-write.1.0_0_2 > act=open > io 24594 read_iolog2: Making note of file. offset=7310584035475809390 > bytes=811544671 fileno=3 file_action=1 fname=/mnt/ssd3/rand-write.1.0_1_0 > act=open > io 24594 read_iolog2: Making note of file. offset=7310584035475809390 > bytes=811544671 fileno=4 file_action=1 fname=/mnt/ssd4/rand-write.1.0_1_1 > act=open > io 24594 read_iolog2: Making note of file. offset=7310584035475809390 > bytes=811544671 fileno=5 file_action=1 fname=/mnt/ssd5/rand-write.1.0_1_2 > act=open > io 24594 read_iolog2: Making note of file. offset=0 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd0/rand-write.1.0_0_0 act=write > io 24594 read_iolog2: Making note of file. offset=0 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd1/rand-write.1.0_0_1 act=write > io 24594 read_iolog2: Making note of file. offset=0 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd2/rand-write.1.0_0_2 act=write > io 24594 read_iolog2: Making note of file. offset=0 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd3/rand-write.1.0_1_0 act=write > io 24594 read_iolog2: Making note of file. offset=0 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd4/rand-write.1.0_1_1 act=write > io 24594 read_iolog2: Making note of file. offset=0 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd5/rand-write.1.0_1_2 act=write > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd0/rand-write.1.0_0_0 act=write > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd1/rand-write.1.0_0_1 act=write > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd2/rand-write.1.0_0_2 act=write > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd3/rand-write.1.0_1_0 act=write > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd4/rand-write.1.0_1_1 act=write > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=5 file_action=1 fname=/mnt/ssd5/rand-write.1.0_1_2 act=write > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=0 file_action=2 fname=/mnt/ssd0/rand-write.1.0_0_0 act=close > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=1 file_action=2 fname=/mnt/ssd1/rand-write.1.0_0_1 act=close > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=2 file_action=2 fname=/mnt/ssd2/rand-write.1.0_0_2 act=close > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=3 file_action=2 fname=/mnt/ssd3/rand-write.1.0_1_0 act=close > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=4 file_action=2 fname=/mnt/ssd4/rand-write.1.0_1_1 act=close > io 24594 read_iolog2: Making note of file. offset=65536 bytes=65536 > fileno=5 file_action=2 fname=/mnt/ssd5/rand-write.1.0_1_2 act=close > ############## end of debug excerpt ######## > > Taking a look to the debugging output shows that on write action the > 'fileno' variable is always set to 5 regardless of the file that should be > written. However, for open and close we have a different fileno value for > each file. Taking a look into the source code of read_iolog2() reveals why: > In case of actions 'open' or 'close', 'fileno' is looked up through > 'get_fileno(td, fname)', but for 'write', 'read' and the other 4 argument > actions 'fileno' is not looked up. When I add a 'fileno = get_fileno(td, > fname);' at the end of the '(r == 4)' branch, I/Os are replayed to the > designated files. > > ########## excerpt from read_iolog2() within iolog.c ###### > if (r == 4) { > /* > * Check action first > */ > if (!strcmp(act, "wait")) > rw = DDIR_WAIT; > else if (!strcmp(act, "read")) > rw = DDIR_READ; > else if (!strcmp(act, "write")) > rw = DDIR_WRITE; > else if (!strcmp(act, "sync")) > rw = DDIR_SYNC; > else if (!strcmp(act, "datasync")) > rw = DDIR_DATASYNC; > else if (!strcmp(act, "trim")) > rw = DDIR_TRIM; > else { > log_err("fio: bad iolog file action: %s\n", > act); > continue; > } > } else if (r == 2) { > rw = DDIR_INVAL; > if (!strcmp(act, "add")) { > td->o.nr_files++; > fileno = add_file(td, fname); > file_action = FIO_LOG_ADD_FILE; > continue; > } else if (!strcmp(act, "open")) { > fileno = get_fileno(td, fname); > file_action = FIO_LOG_OPEN_FILE; > } else if (!strcmp(act, "close")) { > fileno = get_fileno(td, fname); > file_action = FIO_LOG_CLOSE_FILE; > } else { > log_err("fio: bad iolog file action: %s\n", > act); > continue; > } > } else { > log_err("bad iolog2: %s", p); > continue; > } > ########## end ###### Thanks for the detailed and thorough analysis. Care to resend this is a "proper" patch, and I'll get it tested and added too? -- Jens Axboe