Earlier this month Paul reached out to me in private and asked me about a few of my board status uploads. We collectively noticed the romstage now takes significantly longer to the tune of 1.5 seconds. We were not quite sure where the problem was because I also tried reverting to romcc bootblock and I didn't see much improvement.
Now that I have timestamps in i440bx ram init, I ran the tests again, and here are the results. (This time my board status is not uploading correctly...)
With serial console: 0:1st timestamp 741 11:start of bootblock 4,763 (4,021) 12:end of bootblock 4,980 (216) 13:starting to load romstage 6,127 (1,146) 14:finished loading romstage 6,269 (142) 1:start of romstage 6,724 (454) 2:before ram initialization 500,006 (493,282) 3:after ram initialization 670,733 (170,726) 4:end of romstage 2,189,924 (1,519,190) 100:start of postcar 2,311,060 (121,136) 101:end of postcar 2,311,061 (0) 8:starting to load ramstage 2,318,690 (7,629) 15:starting LZMA decompress (ignore for x86) 2,322,877 (4,187) 16:finished LZMA decompress (ignore for x86) 2,361,147 (38,269) 9:finished loading ramstage 2,369,966 (8,818) 10:start of ramstage 2,381,486 (11,519) 30:device enumeration 2,381,490 (4) 40:device configuration 2,447,811 (66,321) 50:device enable 2,649,524 (201,713) 60:device initialization 2,672,956 (23,431) 65:Option ROM initialization 2,819,134 (146,178) 66:Option ROM copy done 2,895,605 (76,471) 67:Option ROM run done 3,249,285 (353,679) 70:device setup done 3,283,763 (34,478) 75:cbmem post 3,287,313 (3,550) 80:write tables 3,287,315 (1) 85:finalize chips 3,427,717 (140,401) 90:load payload 3,431,452 (3,735) 15:starting LZMA decompress (ignore for x86) 3,460,849 (29,396) 16:finished LZMA decompress (ignore for x86) 3,517,611 (56,762) 99:selfboot jump 3,528,778 (11,167)
Total Time: 3,528,022
Without serial console: 0:1st timestamp 742 11:start of bootblock 4,763 (4,021) 12:end of bootblock 4,980 (216) 13:starting to load romstage 6,127 (1,146) 14:finished loading romstage 6,269 (142) 1:start of romstage 6,742 (472) 2:before ram initialization 315,196 (308,454) 3:after ram initialization 486,614 (171,417) 4:end of romstage 1,650,976 (1,164,362) 100:start of postcar 1,722,827 (71,851) 101:end of postcar 1,722,828 (0) 8:starting to load ramstage 1,722,929 (101) 15:starting LZMA decompress (ignore for x86) 1,722,952 (22) 16:finished LZMA decompress (ignore for x86) 1,761,057 (38,105) 9:finished loading ramstage 1,761,177 (119) 10:start of ramstage 1,762,626 (1,449) 30:device enumeration 1,762,631 (4) 40:device configuration 1,762,816 (185) 50:device enable 1,763,445 (628) 60:device initialization 1,763,542 (97) 65:Option ROM initialization 1,764,321 (778) 66:Option ROM copy done 1,826,366 (62,045) 67:Option ROM run done 2,175,483 (349,116) 70:device setup done 2,175,535 (52) 75:cbmem post 2,175,537 (1) 80:write tables 2,175,539 (2) 85:finalize chips 2,179,763 (4,223) 90:load payload 2,179,768 (5) 15:starting LZMA decompress (ignore for x86) 2,179,995 (226) 16:finished LZMA decompress (ignore for x86) 2,236,000 (56,005) 99:selfboot jump 2,236,034 (33)
Total Time: 2,235,277 ---
So much of the slowdown between after raminit and end of romstage. romstage also spent significant time before entering i440bx raminit. Since this is outside my area, I'll defer to the masters here.
Thanks Keith