tuananh / camaro

camaro is an utility to transform XML to JSON, using Node.js binding to native XML parser pugixml, one of the fastest XML parser around.
MIT License
555 stars 28 forks source link

Latest version very slow on AWS Lambda (node v14) #124

Open ianbale opened 3 years ago

ianbale commented 3 years ago

Describe the bug Camaro 6.1.0 is orders of magnitude slower on AWS Lambda than 3.0.7

I have a complex application that makes use of camaro to decode XML we receive from external systems that we use for creating train tickets. We've been using v3.0.7 for the past year and a half (current version when we built the system).

We've been updating various aspects of the system, including upgrading camaro to v6.1.0

Running locally on Macs everything seemed fine.

Yesterday we deployed the update to AWS Lambda.

Prior to the update, the overall execution time for a seat reservation function was around 3 seconds. After the deploy that has gone up to 20 - 120 seconds.

Increasing the memory allocation from 128Mb to 1576Mb has brought the time back down to around 5-6 seconds.

Today we have trying rolling back various aspects of the upgrade. The only one that made a difference is camaro.

We've extensively tested two builds where the only difference is the version of camaro. We've used the same reservation request to ensure both sets of code have the exact same task to perform.

The version with 3.0.7 is taking 3 seconds with 128Mb of memory allocated to Lambda. The version with 6.1.0 is taking 28 seconds with the same 128Mb of memory allocated to Lambda.

I have logging which counts up timings for the main operations. They show the number of times an operation was called and the total time for all calls combined and average time per call.

With v 3.0.7 on AWS Lambda the logs for camaro show (timings in µs)

        "camaro": {
            "count": 12,
            "total": 2230,
            "average": 186
        },

With 6.1.0 on AWS Lambda they are:

        "camaro": {
            "count": 12,
            "total": 8969821,
            "average": 747486
        },

Running locally on OSX, 6.1.0 timings are:

    "camaro": {
      "count": 12,
      "total": 15777,
      "average": 1315
    },

So it is MUCH faster than running on the mac than on AWS Lambda, but still far slower than 3.0.7 on the Mac:

    "camaro": {
      "count": 12,
      "total": 1149,
      "average": 96
    },

Here is one example of XML and template which took 3559851 µs with 6.1.0 and 73 µs with 3.0.7:

<?xml version="1.0" encoding="UTF-8" standalone="yes"?><BR>    <H m="T" i="RETEST1" v="011805">        <X>8b757231-dd3d-4536-b969-3e8ec8296b43</X>    </H>    <E c="E00328" i="YVJ" j="WAT" e="No availability for requested product on Leg from YVJ to WAT"></E></BR> { error: { code: '//E/@c', message: '//E/@e' } } | 2021-04-07T12:10:19.979Z 8b757231-dd3d-4536-b969-3e8ec8296b43 INFO Camaro 3559851 <?xml version="1.0" encoding="UTF-8" standalone="yes"?> <BR> <H m="T" i="RETEST1" v="011805"> <X>8b757231-dd3d-4536-b969-3e8ec8296b43</X> </H> <E c="E00328" i="YVJ" j="WAT" e="No availability for requested product on Leg from YVJ to WAT"></E> </BR> 

{ error: { code: '//E/@c', message: '//E/@e' } }

and another that took 2579765 µs with 6.1.0 and 443 µs with 3.0.7


<?xml version="1.0" encoding="UTF-8" standalone="yes"?><OP>    <H m="T" i="RETEST1" v="011805">        <X>bf3b1b58-796d-4daa-b957-150b7e824ec3</X>    </H>    <L o="YVJ" d="WAT" s="SW6152" t="11042021" c="1">        <P u="101 ">            <U c="SEAT"></U>        </P>        <P u="102 ">            <U c="SEAT"></U>        </P>        <P u="103 ">            <U c="SEAT"></U>        </P>        <P u="104 ">            <U c="SEAT"></U>        </P>        <P u="105 ">            <U c="SEAT"></U>        </P>        <P u="106 ">            <U c="SEAT"></U>        </P>        <P u="107 ">            <U c="SEAT"></U>        </P>        <P u="108 ">            <U c="SEAT"></U>        </P>        <P u="109 ">            <U c="SEAT"></U>        </P>        <P u="110 ">            <U c="SEAT"></U>        </P>        <P u="111 ">            <U c="SEAT"></U>        </P>        <P u="112 ">            <U c="SEAT"></U>        </P>        <P u="113 ">            <U c="SEAT"></U>        </P>        <P u="114 ">            <U c="SEAT"></U>        </P>        <P u="115 ">            <U c="SEAT"></U>        </P>        <P u="116 ">            <U c="SEAT"></U>        </P>        <P u="117 ">            <U c="SEAT"></U>        </P>        <P u="118 ">            <U c="SEAT"></U>        </P>        <P u="119 ">            <U c="SEAT"></U>        </P>        <P u="120 ">            <U c="SEAT"></U>        </P>        <P u="121 ">            <U c="SEAT"></U>        </P>        <P u="122 ">            <U c="SEAT"></U>        </P>        <P u="123 ">            <U c="SEAT"></U>        </P>        <P u="124 ">            <U c="SEAT"></U>        </P>        <P u="125 ">            <U c="SEAT"></U>        </P>        <P u="126 ">            <U c="SEAT"></U>        </P>        <P u="127 ">            <U c="SEAT"></U>        </P>        <P u="128 ">            <U c="SEAT"></U>        </P>        <P u="129 ">            <U c="SEAT"></U>        </P>        <P u="130 ">            <U c="SEAT"></U>        </P>        <P u="131 ">            <U c="SEAT"></U>        </P>        <P u="132 ">            <U c="SEAT"></U>        </P>        <P u="133 ">            <U c="SEAT"></U>        </P>        <P u="134 ">            <U c="SEAT"></U>        </P>        <P u="135 ">            <U c="SEAT"></U>        </P>        <P u="136 ">            <U c="SEAT"></U>        </P>        <P u="137 ">            <U c="SEAT"></U>        </P>        <P u="138 ">            <U c="SEAT"></U>        </P>        <P u="139 ">            <U c="SEAT"></U>        </P>        <P u="140 ">            <U c="SEAT"></U>        </P>        <P u="141 ">            <U c="SEAT"></U>        </P>        <P u="142 ">            <U c="SEAT"></U>        </P>        <P u="143 ">            <U c="SEAT"></U>        </P>        <P u="144 ">            <U c="SEAT"></U>        </P>        <P u="145 ">            <U c="SEAT"></U>        </P>        <P u="146 ">            <U c="SEAT"></U>        </P>        <P u="147 ">            <U c="SEAT"></U>        </P>        <P u="148 ">            <U c="SEAT"></U>        </P>        <P u="149 ">            <U c="SEAT"></U>        </P>        <P u="150 ">            <U c="SEAT"></U>        </P>        <P u="151 ">            <U c="SEAT"></U>        </P>        <P u="153 ">            <U c="SEAT"></U>        </P>        <P u="154 ">            <U c="SEAT"></U>        </P>        <P u="155 ">            <U c="SEAT"></U>        </P>        <P u="156 ">            <U c="SEAT"></U>        </P>        <P u="157 ">            <U c="SEAT"></U>        </P>        <P u="158 ">            <U c="SEAT"></U>        </P>        <P u="159 ">            <U c="SEAT"></U>        </P>        <P u="160 ">            <U c="SEAT"></U>        </P>        <P u="161 ">            <U c="SEAT"></U>        </P>        <P u="162 ">            <U c="SEAT"></U>        </P>        <P u="163 ">            <U c="SEAT"></U>        </P>        <P u="164 ">            <U c="SEAT"></U>        </P>        <P u="165 ">            <U c="SEAT"></U>        </P>        <P u="166 ">            <U c="SEAT"></U>        </P>        <P u="167 ">            <U c="SEAT"></U>        </P>        <P u="168 ">            <U c="SEAT"></U>        </P>        <P u="169 ">            <U c="SEAT"></U>        </P>        <P u="170 ">            <U c="SEAT"></U>        </P>        <P u="171 ">            <U c="SEAT"></U>        </P>        <P u="172 ">            <U c="SEAT"></U>        </P>        <P u="173 ">            <U c="SEAT"></U>        </P>        <P u="174 ">            <U c="SEAT"></U>        </P>        <P u="175 ">            <U c="SEAT"></U>        </P>        <P u="176 ">            <U c="SEAT"></U>        </P>        <P u="177 ">            <U c="SEAT"></U>        </P>        <P u="178 ">            <U c="SEAT"></U>        </P>        <P u="179 ">            <U c="SEAT"></U>        </P>        <P u="180 ">            <U c="SEAT"></U>        </P>        <P u="181 ">            <U c="SEAT"></U>        </P>        <P u="182 ">            <U c="SEAT"></U>        </P>        <P u="183 ">            <U c="SEAT"></U>        </P>        <P u="184 ">            <U c="SEAT"></U>        </P>        <P u="185 ">            <U c="SEAT"></U>        </P>        <P u="186 ">            <U c="SEAT"></U>        </P>        <P u="187 ">            <U c="SEAT"></U>        </P>        <P u="188 ">            <U c="SEAT"></U>        </P>        <P u="189 ">            <U c="SEAT"></U>        </P>        <P u="190 ">            <U c="SEAT"></U>        </P>        <P u="191 ">            <U c="SEAT"></U>        </P>        <P u="192 ">            <U c="SEAT"></U>        </P>        <P u="193 ">            <U c="SEAT"></U>        </P>        <P u="194 ">            <U c="SEAT"></U>        </P>        <P u="195 ">            <U c="SEAT"></U>        </P>        <P u="196 ">            <U c="SEAT"></U>        </P>        <P u="197 ">            <U c="SEAT"></U>        </P>        <P u="198 ">            <U c="SEAT"></U>        </P>        <P u="199 ">            <U c="SEAT"></U>        </P>        <P u="1100">            <U c="SEAT"></U>        </P>        <P u="1101">            <U c="SEAT"></U>        </P>        <P u="1102">            <U c="SEAT"></U>        </P>        <P u="1103">            <U c="SEAT"></U>        </P>        <P u="1104">            <U c="SEAT"></U>        </P>        <P u="1105">            <U c="SEAT"></U>        </P>        <P u="1106">            <U c="SEAT"></U>        </P>        <P u="1107">            <U c="SEAT"></U>        </P>        <P u="1108">            <U c="SEAT"></U>        </P>        <P u="1109">            <U c="SEAT"></U>        </P>        <P u="1110">            <U c="SEAT"></U>        </P>        <P u="1111">            <U c="SEAT"></U>        </P>        <P u="1112">            <U c="SEAT"></U>        </P>        <P u="1113">            <U c="SEAT"></U>        </P>        <P u="1114">            <U c="SEAT"></U>        </P>        <P u="1115">            <U c="SEAT"></U>        </P>        <P u="1116">            <U c="SEAT"></U>        </P>        <P u="1117">            <U c="SEAT"></U>        </P>        <P u="1118">            <U c="SEAT"></U>        </P>        <P u="1119">            <U c="SEAT"></U>        </P>        <P u="1120">            <U c="SEAT"></U>        </P>        <P u="1121">            <U c="SEAT"></U>        </P>        <P u="1122">            <U c="SEAT"></U>        </P>        <P u="1123">            <U c="SEAT"></U>        </P>        <P u="1124">            <U c="SEAT"></U>        </P>        <P u="1125">            <U c="SEAT"></U>        </P>        <P u="1126">            <U c="SEAT"></U>        </P>        <P u="1127">            <U c="SEAT"></U>        </P>        <P u="1128">            <U c="SEAT"></U>        </P>        <P u="1129">            <U c="SEAT"></U>        </P>        <P u="1130">            <U c="SEAT"></U>        </P>        <P u="1131">            <U c="SEAT"></U>        </P>        <P u="1132">            <U c="SEAT"></U>        </P>        <P u="1133">            <U c="SEAT"></U>        </P>        <P u="1134">            <U c="SEAT"></U>        </P>        <P u="1135">            <U c="SEAT"></U>        </P>        <P u="1136">            <U c="SEAT"></U>        </P>        <P u="1137">            <U c="SEAT"></U>        </P>        <P u="1138">            <U c="SEAT"></U>        </P>        <P u="1139">            <U c="SEAT"></U>        </P>        <P u="1140">            <U c="SEAT"></U>        </P>        <P u="1141">            <U c="SEAT"></U>        </P>        <P u="1142">            <U c="SEAT"></U>        </P>        <P u="1143">            <U c="SEAT"></U>        </P>        <P u="1144">            <U c="SEAT"></U>        </P>        <P u="1145">            <U c="SEAT"></U>        </P>        <P u="1146">            <U c="SEAT"></U>        </P>        <P u="1147">            <U c="SEAT"></U>        </P>        <P u="1148">            <U c="SEAT"></U>        </P>        <P u="1149">            <U c="SEAT"></U>        </P>        <P u="1150">            <U c="SEAT"></U>        </P>        <P u="1151">            <U c="SEAT"></U>        </P>        <P u="1152">            <U c="SEAT"></U>        </P>        <P u="1153">            <U c="SEAT"></U>        </P>        <P u="1154">            <U c="SEAT"></U>        </P>        <P u="1155">            <U c="SEAT"></U>        </P>        <P u="1156">            <U c="SEAT"></U>        </P>        <P u="1157">            <U c="SEAT"></U>        </P>        <P u="1158">            <U c="SEAT"></U>        </P>        <P u="1159">            <U c="SEAT"></U>        </P>        <P u="1160">            <U c="SEAT"></U>        </P>        <P u="1161">            <U c="SEAT"></U>        </P>        <P u="1162">            <U c="SEAT"></U>        </P>        <P u="1163">            <U c="SEAT"></U>        </P>        <P u="1164">            <U c="SEAT"></U>        </P>        <P u="1165">            <U c="SEAT"></U>        </P>        <P u="1166">            <U c="SEAT"></U>        </P>        <P u="1167">            <U c="SEAT"></U>        </P>        <P u="1168">            <U c="SEAT"></U>        </P>        <P u="1169">            <U c="SEAT"></U>        </P>        <P u="1170">            <U c="SEAT"></U>        </P>        <P u="1171">            <U c="SEAT"></U>        </P>        <P u="1172">            <U c="SEAT"></U>        </P>        <P u="1173">            <U c="SEAT"></U>        </P>        <P u="1174">            <U c="SEAT"></U>        </P>        <P u="1175">            <U c="SEAT"></U>        </P>        <P u="1176">            <U c="SEAT"></U>        </P>        <P u="1177">            <U c="SEAT"></U>        </P>        <P u="1178">            <U c="SEAT"></U>        </P>        <P u="1179">            <U c="SEAT"></U>        </P>        <P u="1180">            <U c="SEAT"></U>        </P>        <P u="1181">            <U c="SEAT"></U>        </P>        <P u="1182">            <U c="SEAT"></U>        </P>        <P u="1183">            <U c="SEAT"></U>        </P>        <P u="1184">            <U c="SEAT"></U>        </P>        <P u="1185">            <U c="SEAT"></U>        </P>        <P u="1186">            <U c="SEAT"></U>        </P>        <P u="1187">            <U c="SEAT"></U>        </P>        <P u="1188">            <U c="SEAT"></U>        </P>        <P u="1189">            <U c="SEAT"></U>        </P>        <P u="1190">            <U c="SEAT"></U>        </P>        <P u="1191">            <U c="SEAT"></U>        </P>        <P u="1192">            <U c="SEAT"></U>        </P>        <P u="1193">            <U c="SEAT"></U>        </P>        <P u="1194">            <U c="SEAT"></U>        </P>        <P u="1195">            <U c="SEAT"></U>        </P>        <P u="1196">            <U c="SEAT"></U>        </P>        <P u="1197">            <U c="SEAT"></U>        </P>    </L></OP> 

{ accom: [ 'OP/L/P', 'translate(@u," ","")' ] } 

Over repeated runs, both of those examples had times in the 100s as well and in the millions (µs). However, out of the 12 calls there was always at least two that were in the millions.

I can speed things up a fair bit by adding some locking around the camaro calls to ensure camaro is never processing more than one XML file at a time.

Digging through past issues I can see that the slow down came in v4 with the introduction of WebAssembly. I saw mention of example using piscina to create worker pools for processing file sin parallel. However, these have gone so I presume that the need for them has gone too?

Is what i am seeing in terms of speed still expected with v6? Is there any solution to having speeds like v3 other than to stick with v3?

Our other dependencies are:

    "async-lock": "^1.2.0",
    "axios": "^0.21.1",
    "axios-retry": "^3.1.9",
    "camaro": "^3.0.7",
    "cuid": "^2.1.4",
    "lodash": "^4.17.21",
    "moment-timezone": "^0.5.27",
    "mysql2": "^1.6.3",
    "node-zip": "^1.1.1",
    "serialize-error": "^8.0.1",
    "xmlbuilder": "^10.1.1"

Expected behaviour I'd expect 6.1.0 to comparable in speed to 3.0.7

tuananh commented 3 years ago

There's not much change from 3 to 6 rather than webassembly. so version 3 is fine.

However, I still want to dig deep into this. I will try with aws lambda sometimes later this week if i have time.

ianbale commented 3 years ago

3.0.7 is still working absolutely fine for me. Does everything I need, so more than happy to sticker with it.

The only slight awkwardness is having to have two versions, one to run locally and one to upload to AWS.

So if the performance issue can be addressed dit would be good to upgrade at some point for the deployment convenience.

Thanks again for making this brilliant library available to us!

ianbale commented 12 months ago

Hi,

I'm still using your great library (v 3.0.19). I'm now using an M2 Mac for development which doesn't play nicely with 3.0.7 but works well with 3.0.19.

Similarly 3.0.19 works great on AWS.

However, I'd very much like to using AWS arm64 architecture rather than i86.

Any chance you could provide a binary for Node18 and AWS arm64?