From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Subject: Re: Missing log entries and other questions References: <036a01d19f62$717af530$5470df90$@cox.net> <20160427203823.GB25397@kernel.dk> <572A02B9.1040902@kernel.dk> <572A24AC.5090106@kernel.dk> <572A60D1.3050700@kernel.dk> <572CD05A.6050404@kernel.dk> <338fdf0f-36fc-e5bf-2380-351672034a58@gmail.com> From: Jens Axboe Message-ID: <572CD802.7050701@kernel.dk> Date: Fri, 6 May 2016 11:44:34 -0600 MIME-Version: 1.0 In-Reply-To: <338fdf0f-36fc-e5bf-2380-351672034a58@gmail.com> Content-Type: text/plain; charset=windows-1252; format=flowed Content-Transfer-Encoding: 7bit To: Mark Nelson , Paul Alcorn Cc: 'Mihkal Dunfjeld' , fio@vger.kernel.org, birger.lunstoeng@stud.ntnu.no List-ID: On 05/06/2016 11:43 AM, Mark Nelson wrote: > > > On 05/06/2016 12:11 PM, Jens Axboe wrote: >> On 05/05/2016 01:36 PM, Mark Nelson wrote: >>> >>> >>> On 05/04/2016 03:51 PM, Jens Axboe wrote: >>>> On 05/04/2016 11:43 AM, Mark Nelson wrote: >>>>> On 05/04/2016 11:34 AM, Jens Axboe wrote: >>>>>> On 05/04/2016 08:10 AM, Jens Axboe wrote: >>>>>>> On 04/27/2016 02:38 PM, Jens Axboe wrote: >>>>>>>> I'll try and see if I can reproduce this. >>>>>>> >>>>>>> So I took a look at your logged output. The way that fio logs is >>>>>>> that it >>>>>>> does it on IO completion. You have set 1s intervals, so it checks, >>>>>>> when >>>>>>> an IO completes, if we're due for logging the previous interval >>>>>>> IOPS: >>>>>>> >>>>>>> spent = mtime_since(&td->iops_sample_time, t); >>>>>>> if (spent < td->o.iops_avg_time) >>>>>>> return; >>>>>>> >>>>>>> If you are doing lots of IO, it matches pretty evenly. But for slow >>>>>>> workloads, it will end up being skewed a bit. It won't be too >>>>>>> hard to >>>>>>> fix the drift, though, but it still won't make it clock precise at >>>>>>> exact >>>>>>> 1s intervals. >>>>>>> >>>>>>> We could move this part into the main thread, and out of the >>>>>>> workers. >>>>>>> Then we could make it more precise. Might not be a bad idea in >>>>>>> general, >>>>>>> since it'll move some of this code out of the fast path. >>>>>>> >>>>>>> I'll take a stab at it. >>>>>> >>>>>> Can you try the below patch? >>>>> >>>>> I'll also try to take a look at this as we've seen a fair amount of >>>>> skew >>>>> in the logs doing fio librbd upstream ceph testing. >>>> >>>> That'd be great. More complete version below, fwiw. >>>> >>>>> I actually wrote a >>>>> first stab at a parser to aggregate logs from multiple fio processes >>>>> with the assumption of non-uniform sampling: >>>>> >>>>> https://github.com/ceph/cbt/blob/master/tools/fiologpaser.py >>>>> >>>>> The idea is you have say 8 fio bw logs in a directory you can do: >>>>> >>>>> fiologparser.py -f *bw* >>>>> >>>>> which will return average values from the logs over user defined >>>>> intervals by taking weighted scores from samples that overlap. You >>>>> can >>>>> also look at per-interval averages, sums, or just a global average. >>>>> >>>>> various option flags: >>>>> >>>>> -i >>>>> -d >>>> -f >>>>> -a >>>>> -s >>>> >>>> That looks useful. Might want to put that in the fio repo as well, if >>>> you are interested. >>> >>> Sure, I'm game. Might be a little buggy and it's definitely slow since >>> I just threw it together the other day. Do you have a place in the repo >>> you like throwing parsing scripts? >> >> Usually I put them in the tools/ directory. > > Done: https://github.com/axboe/fio/pull/170 Merged. I added it to the installable scripts as well. -- Jens Axboe