|
| 1 | + |
| 2 | +import fs from 'fs'; |
| 3 | + |
| 4 | +// |
| 5 | +// the only command line option is to supply the filename. |
| 6 | +// |
| 7 | +// this is a work in progress. |
| 8 | +// |
| 9 | +// definitions: |
| 10 | +// - wrapper - the code that the agent wraps a patched function with |
| 11 | +// - original - the code that the agent is wrapping, e.g., String.prototype.concat |
| 12 | +// - delta - the total difference, for all invocations, between the time taken |
| 13 | +// to execute the wrapper and the time taken to execute the original |
| 14 | +// - deltaPer - delta divided by number of invocations |
| 15 | +// - ratio - the ratio of the wrapper time to the original time. |
| 16 | +// |
| 17 | +// set env var SORT to `delta`, `ratio`, or `deltaPer` to sort the output |
| 18 | +// set env var VERBOSE to 1 to see skipped items. |
| 19 | +// |
| 20 | +const prefixHandlers = { |
| 21 | + 'contrast-ui-reporter': reporter, |
| 22 | + 'patcher': patcher, |
| 23 | +}; |
| 24 | + |
| 25 | +const kRunOrig = ':native:runOriginalFunction'; |
| 26 | +const kRunOrigLen = kRunOrig.length; |
| 27 | +const kWrapper = ':wrapper'; |
| 28 | +const kWrapperLen = kWrapper.length; |
| 29 | +const kPost = ':post'; |
| 30 | +const kPostLen = kPost.length; |
| 31 | +const kPut = ':put'; |
| 32 | +const kPutLen = kPut.length; |
| 33 | +const kGet = ':get'; |
| 34 | +const kGetLen = kGet.length; |
| 35 | + |
| 36 | +const verbose = process.env.VERBOSE === '1'; |
| 37 | + |
| 38 | +const filename = process.argv[2] || 'agent-perf.jsonl'; |
| 39 | + |
| 40 | +let json = fs.readFileSync(filename, 'utf-8'); |
| 41 | + |
| 42 | +json = json.split('\n').slice(0, -1).map(JSON.parse); |
| 43 | + |
| 44 | +let lastRequests = 0; |
| 45 | + |
| 46 | +for (let i = 0; i < json.length; i++) { |
| 47 | + let { timestamp, requests, prefix, measurements } = json[i]; |
| 48 | + |
| 49 | + if (!(prefix in prefixHandlers)) { |
| 50 | + verbose && console.log(`skipping ${timestamp} unknown prefix ${prefix}`); |
| 51 | + continue; |
| 52 | + } |
| 53 | +const prefixLen = prefix.length + 1; |
| 54 | + |
| 55 | + if (requests === lastRequests) { |
| 56 | + verbose && console.log(`skipping ${timestamp} no new requests`); |
| 57 | + continue; |
| 58 | + } |
| 59 | + lastRequests = requests; |
| 60 | + |
| 61 | + |
| 62 | + const summarized = []; |
| 63 | + const unified = {}; |
| 64 | + for (const measurement of measurements) { |
| 65 | + const { tag, n, totalMicros, mean } = measurement; |
| 66 | + if (tag.endsWith(kRunOrig)) { |
| 67 | + const unifiedTag = tag.slice(prefixLen, -kRunOrigLen); |
| 68 | + if (unifiedTag in unified) { |
| 69 | + throw new Error(`wrapper came first1 ${timestamp} ${unifiedTag}`); |
| 70 | + // merge, but this should never happen because the native |
| 71 | + // function should always complete before the wrapper. |
| 72 | + } else { |
| 73 | + unified[unifiedTag] = { tag: unifiedTag, n, nativeMicros: totalMicros, nativeMean: mean }; |
| 74 | + } |
| 75 | + } else if (tag.endsWith(kWrapper)) { |
| 76 | + const unifiedTag = tag.slice(prefixLen, -kWrapperLen); |
| 77 | + if (unifiedTag in unified) { |
| 78 | + unified[unifiedTag].wrapperMicros = totalMicros; |
| 79 | + unified[unifiedTag].wrapperMean = mean; |
| 80 | + |
| 81 | + const ratio = totalMicros / unified[unifiedTag].nativeMicros; |
| 82 | + const delta = totalMicros - unified[unifiedTag].nativeMicros; |
| 83 | + |
| 84 | + unified[unifiedTag].ratio = ratio; |
| 85 | + unified[unifiedTag].delta = delta; |
| 86 | + |
| 87 | + summarized.push(unified[unifiedTag]); |
| 88 | + } else { |
| 89 | + throw new Error(`wrapper came first2 ${timestamp} ${unifiedTag}`); |
| 90 | + // this should never happen either. |
| 91 | + unified[unifiedTag] = { n, wrapperMicros: totalMicros, wrapperMean: mean }; |
| 92 | + } |
| 93 | + } else if (tag.endsWith(kPost)) { |
| 94 | + const unifiedTag = tag.slice(prefixLen, -kPostLen); |
| 95 | + |
| 96 | + unified[unifiedTag] = { n, wrapperMicros: totalMicros, wrapperMean: mean }; |
| 97 | + unified[unifiedTag].tag = unifiedTag + ' post'; |
| 98 | + |
| 99 | + summarized.push(unified[unifiedTag]); |
| 100 | + } else if (tag.endsWith(kPut)) { |
| 101 | + const unifiedTag = tag.slice(prefixLen, -kPutLen); |
| 102 | + |
| 103 | + unified[unifiedTag] = { n, wrapperMicros: totalMicros, wrapperMean: mean }; |
| 104 | + unified[unifiedTag].tag = unifiedTag + ' put'; |
| 105 | + |
| 106 | + summarized.push(unified[unifiedTag]); |
| 107 | + } else if (tag.endsWith(kGet)) { |
| 108 | + const unifiedTag = tag.slice(prefixLen, -kGetLen); |
| 109 | + |
| 110 | + unified[unifiedTag] = { n, wrapperMicros: totalMicros, wrapperMean: mean }; |
| 111 | + unified[unifiedTag].tag = unifiedTag + ' get'; |
| 112 | + |
| 113 | + summarized.push(unified[unifiedTag]); |
| 114 | + } |
| 115 | + |
| 116 | + } |
| 117 | + |
| 118 | + if (summarized.length) { |
| 119 | + if (process.env.SORT === 'delta') { |
| 120 | + summarized.sort(sortDelta); |
| 121 | + } else if (process.env.SORT === 'ratio') { |
| 122 | + summarized.sort(sortRatio); |
| 123 | + } else if (process.env.SORT === 'deltaPer') { |
| 124 | + summarized.sort(sortDeltaPer); |
| 125 | + } |
| 126 | + |
| 127 | + let deltaPerReq = 0; |
| 128 | + |
| 129 | + console.log(`\n${timestamp}`); |
| 130 | + for (const { tag, n, nativeMicros, nativeMean, wrapperMicros, wrapperMean, ratio, delta } of summarized) { |
| 131 | + const raw = `(raw w ${wrapperMean}, o ${nativeMean})`; |
| 132 | + if (ratio) { |
| 133 | + console.log(`${tag} ${n} ratio ${f2(ratio)} delta ${f2(delta)} deltaPer ${f2(delta / n)} ${raw}`); |
| 134 | + } else { |
| 135 | + const raw = `(raw w ${wrapperMean}, total ${wrapperMicros})`; |
| 136 | + console.log(`${tag} ${n} ${raw}`); |
| 137 | + } |
| 138 | + // total number of invocations / requests => invocations/request |
| 139 | + // invocations/request * deltaPer => deltaPerReq |
| 140 | + const deltaPer = delta / n; |
| 141 | + deltaPerReq += (n / requests) * deltaPer; |
| 142 | + // console.log(`${tag} ${n} ${f2(nativeMicros)} ${f2(nativeMean)} ${f2(wrapperMicros)} ${f2(wrapperMean)} ${f2(ratio)} ${f2(delta)}`); |
| 143 | + } |
| 144 | + |
| 145 | + if (deltaPerReq) console.log(`deltaPerReq ${f2(deltaPerReq)}`); |
| 146 | + |
| 147 | + break; |
| 148 | + } |
| 149 | + |
| 150 | +} |
| 151 | + |
| 152 | +function f2(x) { |
| 153 | + return x.toFixed(2); |
| 154 | +} |
| 155 | + |
| 156 | +function sortRatio(a, b) { |
| 157 | + return b.ratio - a.ratio; |
| 158 | +} |
| 159 | + |
| 160 | +function sortDelta(a, b) { |
| 161 | + return b.delta - a.delta; |
| 162 | +} |
| 163 | + |
| 164 | +function sortDeltaPer(a, b) { |
| 165 | + return b.delta / b.n - a.delta / a.n; |
| 166 | +} |
0 commit comments