{"id":4419,"date":"2018-11-19T13:34:55","date_gmt":"2018-11-19T03:34:55","guid":{"rendered":"https:\/\/www.flamingspork.com\/blog\/?p=4419"},"modified":"2018-11-19T13:35:09","modified_gmt":"2018-11-19T03:35:09","slug":"tracing-flash-reads-and-writes-during-boot","status":"publish","type":"post","link":"https:\/\/www.flamingspork.com\/blog\/2018\/11\/19\/tracing-flash-reads-and-writes-during-boot\/","title":{"rendered":"Tracing flash reads (and writes) during boot"},"content":{"rendered":"\n

On OpenPOWER POWER9 systems, we typically talk to the flash chips that hold firmware for the host (i.e. the POWER9) processor through a daemon running on the BMC (aka service processor) rather than directly.<\/p>\n\n\n\n

We have host firmware map “windows” on the LPC bus to parts of the flash chip. This flash chip can in fact be a virtual one, constructed dynamically from files on the BMC.
<\/p>\n\n\n\n

Since we’re mapping windows into this flash address space, we have some knowledge as to what IO the host is doing to\/from the pnor. We can use this to output data in the blktrace format and feed into existing tools used to analyze IO patterns.
<\/p>\n\n\n\n

So, with a bit of learning of the data format and learning how to drive the various tools, I was ready to patch the BMC daemon (mboxbridge) to get some data out.<\/p>\n\n\n\n

An initial bit of data is a graph of the windows into PNOR opened up during an normal boot (see below).
<\/p>\n\n\n\n

\"\"
PNOR windows created over the course of a normal boot.<\/figcaption><\/figure>\n\n\n\n

This shows us that over the course of the boot, we open a bunch of windows, and switch them around a fair bit early on. This makes sense as early in boot we do not yet have DRAM working and page in firmware on-demand into L3 cache.<\/p>\n\n\n\n

Later in boot, you can see the loading of larger chunks of firmware into memory. It’s also possible to see that this seems to take longer than it should – and indeed, we have a bug there.<\/p>\n\n\n\n

Next, by modifying the code again, I introduced recording of when we used a window that the BMC had already cached. While the host will only see one window at a time, the BMC can keep around the ones it prepared earlier in order to avoid IO to the actual flash chips (which are SPI flash, so aren’t incredibly fast).<\/p>\n\n\n\n

Here we can see that we’re likely not doing the most efficient things during boot, and there’s probably room for some optimization.
<\/p>\n\n\n\n

\"\"
Normal boot but including re-used Windows rather than just created ones<\/figcaption><\/figure>\n\n\n\n

Finally, in order to get finer grained information, I reduced the window size from one megabyte down to 4096 bytes. This will impose a heavy speed penalty as it’ll mean we will have to create a lot<\/strong> more windows to do the same amount of IO, but it means that since we’re using the page size of hostboot, we’ll see each individual page in\/out operation that it does during boot.<\/p>\n\n\n\n

So, from the next graph, we can see that there’s several “hot” areas of the image, and on the whole it’s not too many pages. This gives us a hint that a bit of effort to reduce binary image size a little bit could greatly reduce the amount of IO we have to do.
<\/p>\n\n\n\n

\"\"
4096 byte (i.e. page) size window, capturing the bits of flash we need to read in several times due to being low on memory when we’re L3 cache constrained.<\/figcaption><\/figure>\n\n\n\n

The iowatcher tool also can construct a video<\/strong> of the boot and what “blocks” are being read.<\/p>\n\n\n\n