From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mail05.groups.io (mail05.groups.io [45.79.224.7]) by spool.mail.gandi.net (Postfix) with ESMTPS id 786BBD8003E for ; Wed, 4 Dec 2024 04:20:02 +0000 (UTC) DKIM-Signature: a=rsa-sha256; bh=jALAamDE9HxBdNiYhRjMSeoqZF6q3P6FFFjnOSsEbaI=; c=relaxed/simple; d=groups.io; h=Subject:To:From:User-Agent:MIME-Version:Date:Message-ID:Precedence:List-Subscribe:List-Help:Sender:List-Id:Mailing-List:Delivered-To:Reply-To:List-Unsubscribe-Post:List-Unsubscribe:Content-Type; s=20240830; t=1733286002; v=1; x=1733545200; b=f+C7XrjY3iZG0eyEMXCY44frFjcNB2bARRj7ZhU21oLNDv26K9dKzYxREY6WxhTUQfzJGRE5 gsBBnzw0IKIEE62jz6a9r7LObRmX7KmuocCT12jefoK9cTFsq8kLj9UNDVIV1Yiev4pHwDITb25 nxgLLsEpVxJYU980HemZo96K3vrYXxgF5FLW7G3ICUv+j4623+QVx1xzv/Nj//4Ay7XnS71+XxG a4uPCw0MwNWX+nYSdNC50fMRKxDPKy6+iPuXdvPhx+3UrWwN1x/mcjfuHdw1OAZ2IZKmZQVYIDU l824hypq4V4WYA8Dha3EK1gLd9NAr6n8xLJWE4fLERVCw== X-Received: by 127.0.0.2 with SMTP id xiwyYY7687511xLujT4RWuBh; Tue, 03 Dec 2024 20:20:00 -0800 Subject: [edk2-devel] FDF parser performance degrades rapidly on non-trivially sized inputs To: devel@edk2.groups.io From: "davidr via groups.io" X-Originating-Location: Goleta, California, US (68.6.66.197) X-Originating-Platform: Windows Firefox 132 User-Agent: GROUPS.IO Web Poster MIME-Version: 1.0 Date: Wed, 27 Nov 2024 23:55:04 -0800 Message-ID: Precedence: Bulk List-Subscribe: List-Help: Sender: devel@edk2.groups.io List-Id: Mailing-List: list devel@edk2.groups.io; contact devel+owner@edk2.groups.io Reply-To: devel@edk2.groups.io,davidr@ghs.com List-Unsubscribe-Post: List-Unsubscribe=One-Click List-Unsubscribe: X-Gm-Message-State: 7EfQ25HfWobAPSIFZKJqIXuAx7686176AA= Content-Type: multipart/alternative; boundary="4Ot5eG553uFbmgeHeIek" X-GND-Status: LEGIT Authentication-Results: spool.mail.gandi.net; dkim=pass header.d=groups.io header.s=20240830 header.b=f+C7XrjY; spf=pass (spool.mail.gandi.net: domain of bounce@groups.io designates 45.79.224.7 as permitted sender) smtp.mailfrom=bounce@groups.io; dmarc=pass (policy=none) header.from=groups.io --4Ot5eG553uFbmgeHeIek Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Hi, I was testing out dumping a raw OVMF_VARS.fd into an FDF data section and n= oticed that my rebuilds of OVMF with no code changes went from 15 seconds t= o over 1 minute. The only change was the data in the NV_VARIABLE_STORE data= section in OvmfPkg/Include/Fdf/VarStore.fdf.inc which changed the size of = the file from about 4 KiB to about 256 KiB. I was rather curious as to why = my build times changed so much and profiled the build process with cProfile= . Specifically https://github.com/tianocore/edk2/blob/master/BaseTools/Sour= ce/Python/GenFds/FdfParser.py#L279 takes the vast majority of the time. You can reproduce this by adding 256 KiB of "#" characters to the end of Ov= mfPkg/Include/Fdf/VarStore.fdf.inc and building OVMF, which produced this r= esult for me: Build total time: 00:01:31 34883442 function calls (34368868 primitive calls) in 91.191 seconds Ordered by: internal time ncalls =C2=A0tottime =C2=A0percall =C2=A0cumtime =C2=A0percall filename:lin= eno(function) 18769 =C2=A0 73.501 =C2=A0 =C2=A00.004 =C2=A0 75.942 =C2=A0 =C2=A00.004 Fdf= Parser.py:276(_SkipWhiteSpace) 728 =C2=A0 =C2=A05.738 =C2=A0 =C2=A00.008 =C2=A0 =C2=A05.738 =C2=A0 =C2=A00= .008 {method 'acquire' of '_thread.lock' objects} 12 =C2=A0 =C2=A01.569 =C2=A0 =C2=A00.131 =C2=A0 =C2=A01.569 =C2=A0 =C2=A00.= 131 {method 'poll' of 'select.poll' objects} 2849255 =C2=A0 =C2=A01.248 =C2=A0 =C2=A00.000 =C2=A0 =C2=A01.439 =C2=A0 =C2= =A00.000 FdfParser.py:354(_GetOneChar) 2305959 =C2=A0 =C2=A00.873 =C2=A0 =C2=A00.000 =C2=A0 =C2=A01.131 =C2=A0 =C2= =A00.000 FdfParser.py:293(_EndOfFile) 5374641 =C2=A0 =C2=A00.831 =C2=A0 =C2=A00.000 =C2=A0 =C2=A00.831 =C2=A0 =C2= =A00.000 FdfParser.py:368(_CurrentChar) 2 =C2=A0 =C2=A00.526 =C2=A0 =C2=A00.263 =C2=A0 =C2=A01.278 =C2=A0 =C2=A00.6= 39 FdfParser.py:497(PreprocessFile) Changing _SkippedChars from a string to StringIO reduced my build time to 1= 9 seconds: Build total time: 00:00:19 36552029 function calls (36037563 primitive calls) in 18.618 seconds Ordered by: internal time ncalls =C2=A0tottime =C2=A0percall =C2=A0cumtime =C2=A0percall filename:lin= eno(function) 728 =C2=A0 =C2=A05.391 =C2=A0 =C2=A00.007 =C2=A0 =C2=A05.391 =C2=A0 =C2=A00= .007 {method 'acquire' of '_thread.lock' objects} 18769 =C2=A0 =C2=A01.593 =C2=A0 =C2=A00.000 =C2=A0 =C2=A03.452 =C2=A0 =C2= =A00.000 FdfParser.py:277(_SkipWhiteSpace) 12 =C2=A0 =C2=A01.551 =C2=A0 =C2=A00.129 =C2=A0 =C2=A01.551 =C2=A0 =C2=A00.= 129 {method 'poll' of 'select.poll' objects} 2849255 =C2=A0 =C2=A00.850 =C2=A0 =C2=A00.000 =C2=A0 =C2=A00.979 =C2=A0 =C2= =A00.000 FdfParser.py:355(_GetOneChar) 5374641 =C2=A0 =C2=A00.742 =C2=A0 =C2=A00.000 =C2=A0 =C2=A00.742 =C2=A0 =C2= =A00.000 FdfParser.py:369(_CurrentChar) 2305959 =C2=A0 =C2=A00.741 =C2=A0 =C2=A00.000 =C2=A0 =C2=A00.951 =C2=A0 =C2= =A00.000 FdfParser.py:294(_EndOfFile) 2 =C2=A0 =C2=A00.511 =C2=A0 =C2=A00.256 =C2=A0 =C2=A01.237 =C2=A0 =C2=A00.6= 18 FdfParser.py:498(PreprocessFile) All of these tests were run using the python3 binary provided in the docker= container created by https://github.com/tianocore/containers/tree/main/Ubu= ntu-22/Dockerfile ( https://github.com/tianocore/containers/blob/main/Ubunt= u-22/Dockerfile ). This seems like an easy change to make builds a tiny bit faster. Thanks, David -=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D- Groups.io Links: You receive all messages sent to this group. View/Reply Online (#120865): https://edk2.groups.io/g/devel/message/120865 Mute This Topic: https://groups.io/mt/109914552/7686176 Group Owner: devel+owner@edk2.groups.io Unsubscribe: https://edk2.groups.io/g/devel/unsub [rebecca@openfw.io] -=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D- --4Ot5eG553uFbmgeHeIek Content-Type: text/html; charset="utf-8" Content-Transfer-Encoding: quoted-printable
Hi,
 
I was testing out dumping a raw OVMF_VARS.fd into an FDF data section = and noticed that my rebuilds of OVMF with no code changes went from 15 seco= nds to over 1 minute. The only change was the data in the NV_VARIABLE_STORE= data section in OvmfPkg/Include/Fdf/VarStore.fdf.inc which changed the siz= e of the file from about 4 KiB to about 256 KiB. I was rather curious as to= why my build times changed so much and profiled the build process with cPr= ofile. Specifically https://github.com/tianocore/edk2/blob/master/BaseTools/Sourc= e/Python/GenFds/FdfParser.py#L279 takes the vast majority of the time.<= /div>
 
You can reproduce this by adding 256 KiB of "#" characters to the end = of OvmfPkg/Include/Fdf/VarStore.fdf.inc and building OVMF, which produced t= his result for me:
Build total time: 00:01:31
         34883442 function calls (34368868 pr= imitive calls) in 91.191 seconds
   Ordered by: internal time
   ncalls  tottime  percall  cumtime  pe= rcall filename:lineno(function)
    18769   73.501 &nbs= p;  0.004   75.942    0.004 FdfParser.py:276(_SkipWhite= Space)
      728    5.738    0.008 =    5.738    0.008 {method 'acquire' of '_thread.lock' o= bjects}
       12    1.569    = 0.131    1.569    0.131 {method 'poll' of 'select.poll'= objects}
  2849255    1.248    0.000   =  1.439    0.000 FdfParser.py:354(_GetOneChar)
  23= 05959    0.873    0.000    1.131    = ;0.000 FdfParser.py:293(_EndOfFile)
  5374641    0.831 =    0.000    0.831    0.000 FdfParser.py:368(_= CurrentChar)
        2    0.526   &= nbsp;0.263    1.278    0.639 FdfParser.py:497(Preproces= sFile)
 
Changing _SkippedChars from a string to StringIO reduced my build time= to 19 seconds:
Build total time: 00:00:19
         36552029 function calls (36037563 pr= imitive calls) in 18.618 seconds
   Ordered by: internal time
   ncalls  tottime  percall  cumtime  pe= rcall filename:lineno(function)
      728    = 5.391    0.007    5.391    0.007 {method 'acq= uire' of '_thread.lock' objects}
    18769    1.59= 3    0.000    3.452    0.000 FdfParser.py:277= (_SkipWhiteSpace)
       12    1.551 &nb= sp;  0.129    1.551    0.129 {method 'poll' of 'se= lect.poll' objects}
  2849255    0.850    0.0= 00    0.979    0.000 FdfParser.py:355(_GetOneChar)
  5374641    0.742    0.000    0.742 &n= bsp;  0.000 FdfParser.py:369(_CurrentChar)
  2305959   =  0.741    0.000    0.951    0.000 FdfPar= ser.py:294(_EndOfFile)
        2    0.51= 1    0.256    1.237    0.618 FdfParser.py:498= (PreprocessFile)
 
All of these tests were run using the python3 binary provided in the d= ocker container created by https://github.com/tianocore/containers/= tree/main/Ubuntu-22/Dockerfile.
 
This seems like an easy change to make builds a tiny bit faster.
 
Thanks,
David
_._,_._,_
Groups.io Links:

=20 You receive all messages sent to this group. =20 =20

View/Reply Online (#120865) | =20 | Mute= This Topic | New Topic
Your Subscriptio= n | Contact Group Owner | Unsubscribe [rebecca@openfw.io]

_._,_._,_
--4Ot5eG553uFbmgeHeIek--