Skip to content

Instantly share code, notes, and snippets.

@cgiosy
Last active March 14, 2023 18:09
Show Gist options
  • Star 4 You must be signed in to star a gist
  • Fork 1 You must be signed in to fork a gist
  • Save cgiosy/26a140cfc3e2f021ba7b672e7651813a to your computer and use it in GitHub Desktop.
Save cgiosy/26a140cfc3e2f021ba7b672e7651813a to your computer and use it in GitHub Desktop.
const fs = require('fs');
const filenum = 30; // or 100
const lines = 2000000; // or 1000000
const errors = 100000;
const ratio = lines / errors | 0;
const count = lines / ratio | 0;
for (let i = 1; i <= filenum; i += 1) {
const stream = fs.createWriteStream(`test${i}-log.xml`, { flags: 'a' });
let text = `<error><!\[CDATA\[${i}#${Math.random()}\]\]><\/error>\n`;
for (let j = 2; j <= ratio; j += 1)
text += `<info><!\[CDATA\[${i}#${Math.random()}\]\]><\/info>\n`;
text | 0;
for (let j = 1; j <= count; j += 1)
stream.write(text);
stream.end();
}
const { resolve } = require('path');
const { writeFile, readFile, readdir } = require('fs').promises;
const walkDir = (fn, startingDir = '.') => {
const _walkDir = (currentDir) => readdir(currentDir, { withFileTypes: true }).then((children) => Promise.all(
children.map((child) => {
const res = resolve(currentDir, child.name);
if (child.isDirectory()) return _walkDir(res);
return Promise.resolve(fn(res));
})
));
return _walkDir(startingDir);
};
const flatten = (str) => {
str | 0;
return str;
};
const extractErrors = async () => {
const filenames = [];
await walkDir((filename) => {
if (!filename.toLowerCase().endsWith('-log.xml')) return;
filenames.push(filename);
});
let errors = [];
for (const filename of filenames) {
console.log(filename);
const text = await readFile(filename, { encoding: 'utf-8' }); // Out Of Memory! mem usage 97~99%
errors = errors.concat(
(text.match(/<error><!\[CDATA\[(.+?)\]\]><\/error>/g) || [])
.filter(str => !str.includes(' '))
.map(str => str.slice(16, -11))
// .map(flatten)
);
}
await writeFile('errors.txt', JSON.stringify([...new Set(errors)]));
};
setTimeout(extractErrors, 0 * 1000);
@cgiosy
Copy link
Author

cgiosy commented Feb 21, 2022

V8 error log:

<--- Last few GCs --->

[2694:0x140008000]     5713 ms: Mark-sweep (reduce) 1945.6 (1949.5) -> 1927.6 (1932.4) MB, 30.2 / 0.0 ms  (+ 1.2 ms in 13 steps since start of marking, biggest step 0.4 ms, walltime since start of marking 32 ms) (average mu = 0.823, current mu = 0.386) ex[2694:0x140008000]     5991 ms: Mark-sweep (reduce) 2054.6 (2058.3) -> 2054.0 (2056.5) MB, 51.1 / 0.0 ms  (average mu = 0.819, current mu = 0.816) allocation failure scavenge might not succeed


<--- JS stacktrace --->

FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory
 1: 0x103092e84 node::Abort() [/opt/homebrew/Cellar/node/17.4.0/bin/node]
 2: 0x103093e84 node::OnFatalError(char const*, char const*) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
 3: 0x1031eb120 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
 4: 0x1031eb0b4 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
 5: 0x10333aeb8 v8::internal::Heap::EnsureFillerObjectAtTop() [/opt/homebrew/Cellar/node/17.4.0/bin/node]
 6: 0x103339eb8 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
 7: 0x1033468a4 v8::internal::Heap::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
 8: 0x103346924 v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
 9: 0x10331e3bc v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationType, v8::internal::AllocationOrigin) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
10: 0x1035d3654 v8::internal::Runtime_AllocateInYoungGeneration(int, unsigned long*, v8::internal::Isolate*) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
11: 0x102f063ec Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit [/opt/homebrew/Cellar/node/17.4.0/bin/node]
12: 0x102f5a5a8 Builtins_RegExpMatchFast [/opt/homebrew/Cellar/node/17.4.0/bin/node]
13: 0x102f64a90 Builtins_StringPrototypeMatch [/opt/homebrew/Cellar/node/17.4.0/bin/node]
14: 0x1098a4354 
15: 0x102ec9674 Builtins_AsyncFunctionAwaitResolveClosure [/opt/homebrew/Cellar/node/17.4.0/bin/node]
16: 0x102f4e4f8 Builtins_PromiseFulfillReactionJob [/opt/homebrew/Cellar/node/17.4.0/bin/node]
17: 0x102ebba54 Builtins_RunMicrotasks [/opt/homebrew/Cellar/node/17.4.0/bin/node]
18: 0x102e98c84 Builtins_JSRunMicrotasksEntry [/opt/homebrew/Cellar/node/17.4.0/bin/node]
19: 0x1032d734c v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
20: 0x1032d76b8 v8::internal::(anonymous namespace)::InvokeWithTryCatch(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
21: 0x1032f87dc v8::internal::MicrotaskQueue::RunMicrotasks(v8::internal::Isolate*) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
22: 0x1032f8608 v8::internal::MicrotaskQueue::PerformCheckpointInternal(v8::Isolate*) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
23: 0x102fca8b4 node::InternalCallbackScope::Close() [/opt/homebrew/Cellar/node/17.4.0/bin/node]
24: 0x103098940 node::fs::FileHandle::CloseReq::Resolve() [/opt/homebrew/Cellar/node/17.4.0/bin/node]
25: 0x1030990dc node::fs::FileHandle::ClosePromise()::$_0::__invoke(uv_fs_s*) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
26: 0x1052f78c0 uv__work_done [/opt/homebrew/Cellar/libuv/1.43.0/lib/libuv.1.dylib]
27: 0x1052fac38 uv__async_io [/opt/homebrew/Cellar/libuv/1.43.0/lib/libuv.1.dylib]
28: 0x10530a458 uv__io_poll [/opt/homebrew/Cellar/libuv/1.43.0/lib/libuv.1.dylib]
29: 0x1052fb058 uv_run [/opt/homebrew/Cellar/libuv/1.43.0/lib/libuv.1.dylib]
30: 0x102fcba60 node::SpinEventLoop(node::Environment*) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
31: 0x1030d07d0 node::NodeMainInstance::Run(int*, node::Environment*) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
32: 0x1030d0424 node::NodeMainInstance::Run(node::EnvSerializeInfo const*) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
33: 0x103060b40 node::Start(int, char**) [/opt/homebrew/Cellar/node/17.4.0/bin/node]
34: 0x1055050f4

@cgiosy
Copy link
Author

cgiosy commented Feb 21, 2022

삽질 과정:

  1. 100~200MB 정도의 로그 파일 30 ~ 100개에서 특정 문자열을 찾아 분석해야 했다.
  2. 적당히 짜고 노드로 실행시켰더니 메모리 초과가 떴다. substr때문에 GC가 안 도는구나 싶어 flatten 함수를 추가했다. (기존에 알려져 있던 대로라면 str | 0 혹은 Number(str) 처럼 하면 문자열이 flatten되어 slice에 대한 참조가 해제되어야 한다. #1 #2)
  3. 다시 돌려봤으나 상황이 바뀌지 않았다. flatten이 잘못되었나 싶어 다른 방법으로 좀 수정해보거나((str += ' ') | 0 등), substr을 지워봤다. 문제는 그대로였다.
  4. inspect로 연결해 확인해 보니 toString에서 메모리의 98%를 차지했다. UCS-2로의 변환이 문제거나 뭔가 내부적으로 비효율적인 게 아닐까 추측했다.
  5. stream을 사용해보거나 노드 옵션을 통해 최대 메모리를 늘리는 방법을 고려해보았다. 하지만 근본적인 문제를 해결하지 않고 도피하는 선택이었고 일단 짜기 귀찮았다.
  6. 진전이 없었다. 질문 글을 올렸다. #
  7. 한동안 댓글에 달리는 추측을 실험해 보았고, 시도할 수록 더더욱 미궁에 빠졌다.
  8. 답변을 얻기 위해 상황 재현을 위한 로그 제네레이터를 짜서 올렸다.
  9. GC가 왜 안 도나 싶어 삽질을 해보던 도중 errors의 길이를 제한하니 (당연하게도) 원하는 답은 안 구해지지만 돌긴 한다는 것을 확인했다. toString 등 변환 과정이 아니라 어디에선가 참조가 해제되지 않고 있다는 생각으로 다시 기울었다.
  10. flatten 함수와 substr 에 대한 검증을 마친 상태였기 때문에, 해당 부분은 문제되지 않을 것이라 생각했다. 그런데 저기를 빼놓고 보니 문제될만한 부분이 없었다. 여전히 답은 보이지 않았다.
  11. slice 참조 해제 관련 문제일 것이란 댓글이 달렸다. substr이 아니라 정규식 match에서도 참조가 생긴단 점은 처음 알았지만, 일단은 앞서 했던 예상 범위 내였다. flatten 함수로 해결되지 않고 있었기 때문에, 좀 다른 부분이 문제일 것이라 생각했다.
  12. 해당 댓글에 다른 사람이 이게 문제가 맞고 여기 있는 방법을 적용했더니 된다는 답글이 달렸다.
  13. 화들짝 놀라서 호다닥 적용해봤다. 진짜 됐다.
  14. 뭐지 싶어서 기존에 안 되던 코드에서 flatten 함수의 str | 0 부분만 str = (' ' + str).slice(1) 로 바꿨다. 됐다.
  15. 범인은 믿고 있던 flatten이었다...!!! 노드가 버전업돼서 그런 것인지 아무 작동도 수행하지 않았고, 따라서 내부적으로 slice에 대한 참조 역시 해제되지 않아 GC가 문자열을 수집하지 못하는 것이었다...!

배운 점:

  1. V8의 특징을 이용한 최적화는 버전이나 환경, 상황에 따라 언제든 무력화될 수 있다.
  2. 직접적으로 substr 계열을 호출하는 것뿐만 아니라 match와 같은 함수도 문자열의 slice를 반환해 참조를 만든다.
  3. 인터넷에 올라와 있는 글, 라이브러리 등을 너무 맹신하지 말자. 틀릴 수도 있고, 맞았지만 최근에 바뀐 내용일 수도 있다.
  4. 고언어나 쓰자

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment