fsflush: what is it doing?

Yesterday I was reading performance related bug reports, trolling for work, when I stumbled upon 5024143. I don't know alot about fsflush, so I did some reading and found that on10's fsflush is keeping some internal statistics concerning it's operation that it isn't sharing ( a kstat would be a good place to start ). So being a curious sort, I whipped up a libkvm(3LIB) consumer to expose fsflush's stats to userland. fsfstat is born! Caveat: on10 required.

Some Example Output

Here is sample output from fsfstat run on a 12-way 4800 with 28G of real memory, mostly idle ( Burninator! ).

trogdor:fsfstat -> sudo ./fsfstat 1
#3594320   SCANNED   PCT EXAMINED   LOCKED MODIFIED COALESCE RELEASES   TIME(ns)
15:08:44    119810   3.3      235        0        0        0        0     340320
15:08:45    119810   6.7      235        0        0        0        0     324880
15:08:46    119810  10.0      235        0        0        0        0     324800
15:08:47    119810  13.3      235        0        0        0        0     318000
15:08:48    119810  16.7      634        2        0        0        0     501840
15:08:49    119810  20.0    13802      773        6        7        0    4269440
15:08:50    119810  23.3      235        0        0        0        0     335520
15:08:51    119810  26.7      235        0        0        0        0     320800
15:08:52    119810  30.0      235        0        0        0        0     317840
15:08:53    119810  33.3      235        0        0        0        0     317360
15:08:54    119810  36.7      235        0        0        0        0     320640
15:08:55    119810  40.0      235        0        0        0        0     323680
15:08:56    119810  43.3      235        0        0        0        0     320400
15:08:57    119810  46.7      235        0        0        0        0     315440
15:08:58    119810  50.0      235        0        0        0        0     318800
15:08:59    119810  53.3      235        0        0        0        0     319440
15:09:00    119810  56.7     6367     3124        0        0        0    7615280
15:09:01    119810  60.0   110739    54692        0        6        0  118389680
15:09:03    119810  63.3    33125    14333      374       10        0   31190320
15:09:04    239620  70.0      470        0        0        0        0     663520
15:09:05    119810  73.3      235        0        0        0        0     324240
15:09:06    119810  76.7      235        0        0        0        0     320080
15:09:07    119810  80.0      235        0        0        0        0     317280
15:09:08    119810  83.3      235        0        0        0        0     319680
15:09:09    119810  86.7      235        0        0        0        0     318640
#3594320   SCANNED   PCT EXAMINED   LOCKED MODIFIED COALESCE RELEASES   TIME(ns)
15:09:10    119810  90.0     6572      773       18        0        0    3049280
15:09:11    119810  93.3   113238      617        4        0        0   20368080
15:09:12    119810  96.7   103493        0        0       21        0   17344240
15:09:13    119810 100.0      235        0        0        0        0     346960
15:09:14    119810   3.3      235        0        0        0        0     321040
15:09:15    119810   6.7      235        0        0        0        0     324240
15:09:16    119810  10.0      235        0        0        0        0     322960
15:09:17    119810  13.3      235        0        0        0        0     318400
15:09:18    119810  16.7     2139       96        0        0        0    1095680
15:09:19    119810  20.0    12249      679        6        0        0    3521120
15:09:20    119810  23.3      235        0        0        0        0     334400
15:09:21    119810  26.7      235        0        0        0        0     326960
15:09:22    119810  30.0      235        0        0        0        0     325840
15:09:23    119810  33.3      235        0        0        0        0     320240
15:09:24    119810  36.7      235        0        0        0        0     316720
15:09:25    119810  40.0      235        0        0        0        0     317040
15:09:26    119810  43.3      235        0        0        0        0     316640
15:09:27    119810  46.7      235        0        0        0        0     317120
15:09:28    119810  50.0      235        0        0        0        0     317040
15:09:29    119810  53.3      235        0        0        0        0     317600
15:09:30    119810  56.7    13010     6448        0        0        0   15070240
15:09:31    119810  60.0   115114    56225      109        0        0  121045120
15:09:32    119810  63.3    21994     9476      265        0        0   20595040
15:09:33    119810  66.7      235        0        0        0        0     339840
15:09:34    119810  70.0      235        0        0        0        0     319760

The first column is a timestamp, the second column is number of 8k pages scanned. The fourth column is number of pages examined, which can be a smaller number due to larger pages being composed of sets of smaller pages. Locked, modified, coalesce and release I'm still foggy on ( I need to read and understand fsflush.c some more ). The final column is the time in nanoseconds that fsflush ran over the previous interval. I've saved the third column for last because I thought I was being rather clever. The third column tracks how far thru memory fsflush has scanned since fsfstat has been observing it. In this way, we can tell when fsflush has made a complete sweep thru physical memory and is starting over again.

Some Interesting Observations

Using the locality information gained by the percentage progress thru memory, we can see a pattern emerging in the sample data. Starting at the 20%, 56% and 90% range, we see three second bursts of activity that recurr. I don't have a definite explanation for this activity, and I wouldn't mind hearing thoughts about what's going on here.

Anyway, today is a double-two-fer :) I'm just happy with how this hack turned out.

-ejo

Comments:

Now when will \*that\* be in Solaris? :)

Posted by Torrey McMahon on July 23, 2004 at 09:13 AM CDT #

Please tell me that you have since logged an rfe to get that informartion into a kstat. The side effect of this would be that we should also get Dtrace probe points at the places in which the counters are incremented.

alan.

Posted by Alan Hargreaves on July 25, 2004 at 01:32 PM CDT #

Check. Filed 5078416 today to address this problem. -ejo

Posted by Erik O'Shaughnessy on July 26, 2004 at 05:53 AM CDT #

Turns out that the build rules preclude RFEs from now until FCS, so it will be some time before fsflush offically exports it's stats to user-land.

Bummed.

-ejp

Posted by Erik O'Shaughnessy on July 27, 2004 at 02:52 AM CDT #

I've just put up a simple version of this in D on my blog . It's not as nice as yours Erik.

Posted by Jon Haslam on July 27, 2004 at 04:56 AM CDT #

Post a Comment:
Comments are closed for this entry.
About

ejo

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today
Bookmarks