Investigate flaky test-tick-processor #4427

Trott · 2015-12-26T16:25:19Z

Failure on windows CI: https://ci.nodejs.org/job/node-test-binary-windows/395/RUN_SUBSET=1,VS_VERSION=vs2013,label=win2008r2/tapTestReport/test.tap-189/

Trott · 2015-12-26T18:22:49Z

Confirmed via https://ci.nodejs.org/job/node-stress-single-test/208/nodes=win-vs2013/console but indirectly. It's been hung for a long time now, which would timeout in regular CI.

(/cc @joaocgreis Am I right that there's no timeout on the stress test? Would it be easy to add in Jenkins? Or should I use a wrapper in JS that runs the test with a timeout?)

jbergstroem · 2015-12-26T18:47:57Z

@Trott timeout only seems to be passed to tools/test.py as a flag which means it'll be tricky to create something that won't break branches that would lack that patch (for instance checking flag or environment)

Trott · 2015-12-26T23:34:09Z

Failure on Debian 8: https://ci.nodejs.org/job/node-test-commit-linux/1600/nodes=debian8-64/console

Trott · 2015-12-26T23:34:47Z

I don't think extending the timeout would help after all. I suspect the test is actually hanging indefinitely.

joaocgreis · 2015-12-28T14:29:32Z

@Trott you're right, the stress-single-test job has no timeout.

If someone wants to change test.py to support running a single test instead of a group of tests, that would be great.

Trott · 2015-12-30T05:35:49Z

@joaocgreis As it is currently written, it can run a single test like this:

tools/test.py --mode=release parallel/test-buffer-indexof

Is that what you need? If not, can you explain a bit more? I'm totally up for hacking on test.py if it improves our ability to exercise flaky tests.

joaocgreis · 2015-12-30T16:21:45Z

@Trott I didn't know about that, thanks!

Now it's using the test runner.

Trott · 2016-01-01T20:08:59Z

@joaocgreis That's great! One tweak: If I'm understanding what's going on correctly, it now appears to take into account if the test is marked flaky. (At least, that is consistent with what I'm seeing trying to run stress tests...) For the stress test, we probably always want to ignore the flaky designation and fail if the test failed. Can we pass in the command line flag to tell it to fail if a flaky test fails?

Trott · 2016-01-02T05:25:04Z

So back to the original problem here, with the test being flaky on Windows... /cc @matthewloring

Trott · 2016-01-02T05:25:39Z

Stress test for good measure showing it still times out sometimes on Windows: https://ci.nodejs.org/job/node-stress-single-test/282/nodes=win2012r2/console

Gotta be the first half of the test because the second half is skipped on Windows...

matthewloring · 2016-01-02T19:59:58Z

@Trott I can look into this. The only part of that test that should take time is running the code to be profiled:

function f() {
  for (var i = 0; i < 1000000; i++) {
    i++;
  }
  setImmediate(function() { f(); });
};
setTimeout(function() { process.exit(0); }, 2000);
f();

The stress test output has a lot of lines saying: duration_ms: 3.122. Is the test terminating in 3 ms each time or is that a measurement in seconds?

Trott · 2016-01-02T21:27:25Z

@matthewloring It's a measurement in seconds. (Yeah, I really dislike the _ms part too.)

Trott · 2016-01-02T21:28:32Z

So anyway, yeah, something funky is happening because the test takes about 3 seconds to run most times, but then once in a while, it times out (which means taking more than 60 seconds).

Trott · 2016-01-03T22:45:44Z

Seems to fail on the Rackspace hosts but I wonder if it ever fails on the Microsoft Azure hosts. Let's find out.

Stress test on Microsoft Azure host:
https://ci.nodejs.org/job/node-stress-single-test/292/nodes=win2012r2-1p/console

I believe the main difference between our Rackspace hosts and Azure hosts is that the Rackspace ones are multiprocessor and the Azure ones are single processor.

EDIT: Looks like it fails on both.

joaocgreis · 2016-01-05T18:58:15Z

@Trott re node-stress-single-test using the test runner and flaky tests: the test runnier is using the default --flaky-tests=run, that prints a todo when the test passes but fails when the test fails. In test-commit we are using --flaky-tests=dontcare to run but ignore failures. I tested it here, let me know if I misunderstood something (perhaps reopen #3854).

Trott · 2016-01-05T19:37:06Z

@joaocgreis My mistake, I guess! It sure looks like it works the way you say. Thanks!

Trott · 2016-01-19T04:32:56Z

ping/bump/whatever @matthewloring and @nodejs/platform-windows Thanks in advance for any help anyone can provide in moving this forward.

matthewloring · 2016-01-19T20:34:15Z

@Trott I ran the test in a loop for 4000 iterations (I stopped it after a few hours) and couldn't reproduce the timeout in my local environment. I'm testing on a Windows 7 vm (single core, 2GB ram). Do you have any suggestions on environment changes that should be made to faithfully model the test environment?

Trott · 2016-01-19T22:47:14Z

@matthewloring I'm not sure how that compares to our CI hosts. Help, @nodejs/build? (It fails on both the Rackspace and the Azure Windows hosts.)

I do know that on CI it fails on Windows 2008 and Windows 2012 servers. I don't think we have any Windows 7 servers in CI, so that's one difference there...

santigimeno · 2016-01-21T15:26:48Z

@Trott this failed me a couple of times yesterday in Debian Jessie 64. I haven't been able to reproduce it since then.

Trott · 2016-01-21T23:14:02Z

@santigimeno When you say it failed, did it hang/timeout? Or did it report something?

santigimeno · 2016-01-21T23:23:01Z

@Trott Sorry, it timed out

Trott · 2016-01-21T23:30:02Z

@matthewloring What's the reason that instead of this:

function f() {
  for (var i = 0; i < 1000000; i++) {
    i++;
  }
  setImmediate(function() { f(); });
};
setTimeout(function() { process.exit(0); }, 2000);
f();

...we can't just do this:

function f() {
  for (var i = 0; i < 1e6; i++) {}
};
f();

I'm sure there's a reason, and I've probably had this explained to me before. (I'll try to summarize it in a code comment or something this time.) Something to do with preventing optimization or something like that?

Ref: nodejs#4427

matthewloring · 2016-01-21T23:58:39Z

@Trott The goal of the setImmediate pattern is to ensure that the test runs for a fixed amount of time regardless of the speed of the processor on which the test runs. It was difficult to find a number of iterations that ran long enough on the fast machines to gather enough samples without timing out on slower machines.

PR-URL: nodejs#4809 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Johan Bergström <[email protected]> Reviewed-By: James M Snell <[email protected]> Ref: nodejs#4427

Trott · 2016-06-29T22:29:30Z

I ran a stress test on this on every readily-available platform on CI: https://ci.nodejs.org/job/node-stress-single-test/762/

Failing platforms: armv7-ubuntu1404, osx1010, ubuntu1404-32, win10-1p, win2008r2, win2008r2-p1, win2012r2, win2012r2-p1

A few more may fail--not all have finished running as of right now.

Seems that the problem is especially pronounced on Windows.

Here's a sample failure on win10-p1:

not ok 1 parallel/test-tick-processor
# child_process.js:509
#     throw err;
#     ^
# 
# Error: Command failed: c:\workspace\node-stress-single-test\nodes\win10-1p\Release\node.exe -prof -pe function f() {
#            for (var i = 0; i < 1000000; i++) {
#              i++;
#            }
#            setImmediate(function() { f(); });
#          };
#          setTimeout(function() { process.exit(0); }, 2000);
#          f();
# 
#     at checkExecSyncError (child_process.js:486:13)
#     at Object.execFileSync (child_process.js:506:13)
#     at runTest (C:\workspace\node-stress-single-test\nodes\win10-1p\test\parallel\test-tick-processor.js:47:6)
#     at Object.<anonymous> (C:\workspace\node-stress-single-test\nodes\win10-1p\test\parallel\test-tick-processor.js:21:1)
#     at Module._compile (module.js:541:32)
#     at Object.Module._extensions..js (module.js:550:10)
#     at Module.load (module.js:458:32)
#     at tryModuleLoad (module.js:417:12)
#     at Function.Module._load (module.js:409:3)
#     at Module.runMain (module.js:575:10)
  ---
  duration_ms: 0.604
  ...

JoeDoyle23 · 2016-07-09T00:46:19Z

PR in for preventing the hang.

The question I have is really about what this test should be testing? The name suggests that we're testing the tick processor, but what its really testing is that the test function f() is compiled by V8 in the normal execution mode, and when the VM has the Debug context enabled (on only some OSs).

If anyone has any guidance on what exactly this should be testing, I'd be happy to continue improving it.

matthewloring · 2016-07-09T02:39:56Z

This test is designed test correctness of the integration of the V8 tick processor with Node.js. Despite sharing the name, process.nextTick is unrelated.

JoeDoyle23 · 2016-07-09T02:43:25Z

Ahh, thanks. That makes sense.

Trott · 2016-07-12T22:30:35Z

Typical problem is a timeout:

not ok 1 parallel/test-tick-processor
# TIMEOUT
  ---
  duration_ms: 60.93

Like, the process.exit(0) is failing or the timer is never firing, somehow...

Trott · 2016-09-14T00:10:24Z

Small sample size, but it sure seems like the test is failing a lot more since #8480 landed earlier today.

Maybe that provides some clue as to how it might be fixed for good?

Looping in stats-ish people along with usual suspects because
¯_(ツ)_/¯ @not-an-aardvark @AndreasMadsen @matthewloring @indutny

Trott · 2016-09-14T00:18:10Z

Actually, it looks like it's failing in a different way now, and more frequently. :-/ Is it possible we've broken the v8 profiling integration on some platforms now?

Some sample failures:

https://ci.nodejs.org/job/node-test-commit-linuxone/1136/nodes=rhel72-s390x/console

Click here for details

not ok 1089 parallel/test-tick-processor # TODO : Fix flaky test
# 
# assert.js:85
#   throw new assert.AssertionError({
#   ^
# AssertionError: /Builtin_DateNow/ not matching Statistical profiling result from isolate-0xa3aad810-v8.log, (1777 ticks, 67 unaccounted, 0 excluded).
# 
#  [Shared libraries]:
#    ticks  total  nonlib   name
#     713   40.1%          /usr/lib64/libc-2.17.so
#      33    1.9%          [vdso]
# 
#  [JavaScript]:
#    ticks  total  nonlib   name
#      20    1.1%    1.9%  LazyCompile: *exports.setImmediate timers.js:599:32
#      16    0.9%    1.6%  Stub: JSEntryStub
#      13    0.7%    1.3%  LazyCompile: tryOnImmediate timers.js:550:24
#       9    0.5%    0.9%  LazyCompile: *runCallback timers.js:568:21
#       7    0.4%    0.7%  LazyCompile: ~<anonymous> [eval]:3:33
#       7    0.4%    0.7%  LazyCompile: *emitPendingUnhandledRejections internal/process/promises.js:49:42
#       6    0.3%    0.6%  Builtin: JSConstructStubGeneric
#       5    0.3%    0.5%  Stub: LoadICStub
#       5    0.3%    0.5%  Stub: CallConstructStub
#       4    0.2%    0.4%  Stub: CallApiCallbackStub
#       4    0.2%    0.4%  LazyCompile: *processImmediate timers.js:516:26
#       3    0.2%    0.3%  Stub: FastNewClosureStub
#       3    0.2%    0.3%  Stub: CEntryStub
#       3    0.2%    0.3%  Builtin: ArgumentsAdaptorTrampoline
#       2    0.1%    0.2%  LazyCompile: *f [eval]:1:11
#       2    0.1%    0.2%  Builtin: CallFunction_ReceiverIsNotNullOrUndefined
#       1    0.1%    0.1%  Stub: FastNewObjectStub
#       1    0.1%    0.1%  LazyCompile: ~emitPendingUnhandledRejections internal/process/promises.js:49:42
#       1    0.1%    0.1%  Builtin: CallFunction_ReceiverIsAny
# 
#  [C++]:
#    ticks  total  nonlib   name
#     277   15.6%   26.9%  syscall
#      32    1.8%    3.1%  __GI__IO_vfprintf
#      25    1.4%    2.4%  v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
#      23    1.3%    2.2%  node::MakeCallback(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*)
#      22    1.2%    2.1%  v8::Context::Exit()
#      22    1.2%    2.1%  _itoa_word
#      21    1.2%    2.0%  v8::internal::NameDictionaryBase<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::FindEntry(v8::internal::Handle<v8::internal::Name>)
#      19    1.1%    1.8%  v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
#      16    0.9%    1.6%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
#      15    0.8%    1.5%  __GI___pthread_mutex_lock
#      15    0.8%    1.5%  __GI__IO_default_xsputn
#      14    0.8%    1.4%  v8::Isolate::GetCurrentContext()
#      13    0.7%    1.3%  v8::internal::LookupIterator::GetAccessors() const
#      13    0.7%    1.3%  v8::Function::Call(v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
#      13    0.7%    1.3%  v8::Context::Enter()
#      12    0.7%    1.2%  v8::internal::LookupIterator::PropertyOrElement(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, bool*, v8::internal::LookupIterator::Configuration)
#      11    0.6%    1.1%  void v8::internal::LookupIterator::NextInternal<false>(v8::internal::Map*, v8::internal::JSReceiver*)
#      11    0.6%    1.1%  v8::internal::Object::GetProperty(v8::internal::LookupIterator*)
#      11    0.6%    1.1%  node::NeedImmediateCallbackGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
#      11    0.6%    1.1%  __GI___pthread_getspecific
#      10    0.6%    1.0%  v8::EscapableHandleScope::Escape(v8::internal::Object**)
#       9    0.5%    0.9%  v8::internal::LookupIterator::State v8::internal::LookupIterator::LookupInRegularHolder<false>(v8::internal::Map*, v8::internal::JSReceiver*) [clone .part.111]
#       9    0.5%    0.9%  fwrite
#       9    0.5%    0.9%  __clock_gettime
#       8    0.5%    0.8%  v8::Object::Get(v8::Local<v8::Context>, v8::Local<v8::Value>)
#       8    0.5%    0.8%  __lll_lock_wait
#       7    0.4%    0.7%  void v8::internal::LookupIterator::Start<false>()
#       7    0.4%    0.7%  v8::internal::HandleScope::DeleteExtensions(v8::internal::Isolate*)
#       7    0.4%    0.7%  v8::Isolate::SuppressMicrotaskExecutionScope::SuppressMicrotaskExecutionScope(v8::Isolate*)
#       7    0.4%    0.7%  uv_run
#       5    0.3%    0.5%  v8::internal::ThreadId::GetCurrentThreadId()
#       5    0.3%    0.5%  v8::internal::Runtime::GetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>)
#       5    0.3%    0.5%  v8::internal::Isolate::RunMicrotasksInternal()
#       5    0.3%    0.5%  v8::Isolate::SuppressMicrotaskExecutionScope::~SuppressMicrotaskExecutionScope()
#       5    0.3%    0.5%  v8::Isolate::RunMicrotasks()
#       5    0.3%    0.5%  uv__run_timers
#       5    0.3%    0.5%  strchrnul
#       5    0.3%    0.5%  fflush
#       4    0.2%    0.4%  v8::internal::Runtime_GetProperty(int, v8::internal::Object**, v8::internal::Isolate*)
#       4    0.2%    0.4%  v8::internal::Log::MessageBuilder::Append(char const*, ...)
#       4    0.2%    0.4%  v8::base::TimeTicks::HighResolutionNow()
#       4    0.2%    0.4%  uv__hrtime
#       4    0.2%    0.4%  __libc_enable_asynccancel
#       4    0.2%    0.4%  __GI__IO_setb
#       3    0.2%    0.3%  v8::platform::DefaultPlatform::PumpMessageLoop(v8::Isolate*)
#       3    0.2%    0.3%  v8::internal::TimerEventScope<v8::internal::TimerEventExecute>::LogTimerEvent(v8::internal::Logger::StartEnd)
#       3    0.2%    0.3%  v8::internal::StoreBuffer::MoveEntriesToRememberedSet()
#       3    0.2%    0.3%  v8::internal::SaveContext::SaveContext(v8::internal::Isolate*)
#       3    0.2%    0.3%  v8::internal::Object::GetPropertyWithAccessor(v8::internal::LookupIterator*)
#       3    0.2%    0.3%  v8::internal::LookupIterator::GetDataValue() const
#       3    0.2%    0.3%  memcpy_z196
#       3    0.2%    0.3%  _IO_old_init
#       3    0.2%    0.3%  _IO_no_init
#       2    0.1%    0.2%  v8::platform::DefaultPlatform::PopTaskInMainThreadDelayedQueue(v8::Isolate*)
#       2    0.1%    0.2%  v8::internal::StackFrameIterator::StackFrameIterator(v8::internal::Isolate*)
#       2    0.1%    0.2%  v8::internal::SaveContext::~SaveContext()
#       2    0.1%    0.2%  v8::internal::PerIsolateAssertScope<(v8::internal::PerIsolateAssertType)0, true>::IsAllowed(v8::internal::Isolate*)
#       2    0.1%    0.2%  v8::internal::Logger::ApiEntryCall(char const*)
#       2    0.1%    0.2%  v8::internal::Log::MessageBuilder::WriteToLogFile()
#       2    0.1%    0.2%  v8::internal::Heap::Scavenge()
#       2    0.1%    0.2%  v8::base::Time::ToJsTime() const
#       2    0.1%    0.2%  v8::Value::IsObject() const
#       2    0.1%    0.2%  v8::Value::IsFunction() const
#       2    0.1%    0.2%  v8::V8::GetEternal(v8::Isolate*, int)
#       2    0.1%    0.2%  v8::Object::Get(v8::Local<v8::Value>)
#       2    0.1%    0.2%  v8::(anonymous namespace)::CallDepthScope::~CallDepthScope()
#       2    0.1%    0.2%  uv__run_prepare
#       2    0.1%    0.2%  uv__run_check
#       2    0.1%    0.2%  node::CheckImmediate(uv_check_s*)
#       2    0.1%    0.2%  do_futex_wait
#       2    0.1%    0.2%  __GI_mempcpy
#       2    0.1%    0.2%  __GI___pthread_mutex_unlock
#       2    0.1%    0.2%  __GI__IO_file_xsputn
#       2    0.1%    0.2%  _IO_file_write@@GLIBC_2.2
#       1    0.1%    0.1%  v8::internal::VariableProxy::AssignFeedbackVectorSlots(v8::internal::Isolate*, v8::internal::FeedbackVectorSpec*, v8::internal::FeedbackVectorSlotCache*)
#       1    0.1%    0.1%  v8::internal::TemplateHashMapImpl<v8::internal::FreeStoreAllocationPolicy>::LookupOrInsert(void*, unsigned int, v8::internal::FreeStoreAllocationPolicy) [clone .isra.49]
#       1    0.1%    0.1%  v8::internal::StackFrame::GetCallerState(v8::internal::StackFrame::State*) const
#       1    0.1%    0.1%  v8::internal::ScavengeVisitor::VisitPointers(v8::internal::Object**, v8::internal::Object**)
#       1    0.1%    0.1%  v8::internal::PropertyHandlerCompiler::CheckPrototypes(v8::internal::Register, v8::internal::Register, v8::internal::Register, v8::internal::Register, v8::internal::Handle<v8::internal::Name>, v8::internal::Label*, v8::internal::PrototypeCheckType, v8::internal::ReturnHolder)
#       1    0.1%    0.1%  v8::internal::PerIsolateAssertScope<(v8::internal::PerIsolateAssertType)1, false>::IsAllowed(v8::internal::Isolate*)
#       1    0.1%    0.1%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseAssignmentExpression(bool, v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.1%    0.1%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseAndClassifyIdentifier(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.1%    0.1%  v8::internal::Map::Reconfigure(v8::internal::Handle<v8::internal::Map>, v8::internal::ElementsKind, int, v8::internal::PropertyKind, v8::internal::PropertyAttributes, v8::internal::Representation, v8::internal::Handle<v8::internal::FieldType>, v8::internal::StoreMode)
#       1    0.1%    0.1%  v8::internal::Malloced::Delete(void*)
#       1    0.1%    0.1%  v8::internal::Logger::CurrentTimeEvent()
#       1    0.1%    0.1%  v8::internal::Log::MessageBuilder::MessageBuilder(v8::internal::Log*)
#       1    0.1%    0.1%  v8::internal::LoadWithVectorDescriptor::VectorRegister()
#       1    0.1%    0.1%  v8::internal::List<v8::internal::HBasicBlock*, v8::internal::ZoneAllocationPolicy>::Add(v8::internal::HBasicBlock* const&, v8::internal::ZoneAllocationPolicy)
#       1    0.1%    0.1%  v8::internal::LAllocator::AllocateRegisters()
#       1    0.1%    0.1%  v8::internal::JSDate::CurrentTimeValue(v8::internal::Isolate*)
#       1    0.1%    0.1%  v8::internal::Isolate::RunMicrotasks()
#       1    0.1%    0.1%  v8::internal::Isolate::FireBeforeCallEnteredCallback()
#       1    0.1%    0.1%  v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment)
#       1    0.1%    0.1%  v8::internal::HashTable<v8::internal::StringTable, v8::internal::StringTableShape, v8::internal::HashTableKey*>::FindEntry(v8::internal::Isolate*, v8::internal::HashTableKey*)
#       1    0.1%    0.1%  v8::internal::HOptimizedGraphBuilder::TryArgumentsAccess(v8::internal::Property*)
#       1    0.1%    0.1%  v8::internal::HInstruction::InsertAfter(v8::internal::HInstruction*)
#       1    0.1%    0.1%  v8::internal::HArithmeticBinaryOperation::IsDeletable() const
#       1    0.1%    0.1%  v8::internal::GetICCounts(v8::internal::SharedFunctionInfo*, int*, int*, int*, int*, int*)
#       1    0.1%    0.1%  v8::internal::ExternalCallbackScope::~ExternalCallbackScope()
#       1    0.1%    0.1%  v8::internal::AstRawStringInternalizationKey::IsMatch(v8::internal::Object*)
#       1    0.1%    0.1%  v8::internal::AssemblerPositionsRecorder::RecordStatementPosition(int)
#       1    0.1%    0.1%  v8::internal::AggregatedMemoryHistogram<v8::internal::Histogram>::AddSample(double, double) [clone .part.52]
#       1    0.1%    0.1%  v8::base::Mutex::Lock()
#       1    0.1%    0.1%  v8::Locker::IsActive()
#       1    0.1%    0.1%  v8::EscapableHandleScope::EscapableHandleScope(v8::Isolate*)
#       1    0.1%    0.1%  uv__run_idle
#       1    0.1%    0.1%  uv__io_poll
#       1    0.1%    0.1%  uv__epoll_wait
#       1    0.1%    0.1%  node::RunMicrotasks(v8::FunctionCallbackInfo<v8::Value> const&)
#       1    0.1%    0.1%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
#       1    0.1%    0.1%  cfree
#       1    0.1%    0.1%  _wordcopy_fwd_aligned
#       1    0.1%    0.1%  _init
#       1    0.1%    0.1%  __GI___libc_write
#       1    0.1%    0.1%  __GI__IO_do_write
#       1    0.1%    0.1%  _IO_str_init_static_internal
# 
#  [Summary]:
#    ticks  total  nonlib   name
#     112    6.3%   10.9%  JavaScript
#     852   47.9%   82.6%  C++
#       8    0.5%    0.8%  GC
#     746   42.0%          Shared libraries
#      67    3.8%          Unaccounted
# 
#  [C++ entry points]:
#    ticks    cpp   total   name
#      32   12.9%    1.8%  __GI__IO_vfprintf
#      22    8.9%    1.2%  _itoa_word
#      16    6.5%    0.9%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
#      15    6.0%    0.8%  __GI__IO_default_xsputn
#      13    5.2%    0.7%  v8::internal::LookupIterator::GetAccessors() const
#      11    4.4%    0.6%  node::NeedImmediateCallbackGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
#       9    3.6%    0.5%  fwrite
#       9    3.6%    0.5%  __GI___pthread_mutex_lock
#       8    3.2%    0.5%  v8::internal::NameDictionaryBase<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::FindEntry(v8::internal::Handle<v8::internal::Name>)
#       8    3.2%    0.5%  __lll_lock_wait
#       5    2.0%    0.3%  strchrnul
#       5    2.0%    0.3%  fflush
#       4    1.6%    0.2%  v8::internal::Runtime_GetProperty(int, v8::internal::Object**, v8::internal::Isolate*)
#       4    1.6%    0.2%  v8::internal::Log::MessageBuilder::Append(char const*, ...)
#       4    1.6%    0.2%  v8::base::TimeTicks::HighResolutionNow()
#       4    1.6%    0.2%  v8::Isolate::SuppressMicrotaskExecutionScope::~SuppressMicrotaskExecutionScope()
#       4    1.6%    0.2%  __libc_enable_asynccancel
#       4    1.6%    0.2%  __GI__IO_setb
#       3    1.2%    0.2%  v8::internal::Runtime::GetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>)
#       3    1.2%    0.2%  v8::internal::Object::GetPropertyWithAccessor(v8::internal::LookupIterator*)
#       3    1.2%    0.2%  v8::internal::LookupIterator::PropertyOrElement(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, bool*, v8::internal::LookupIterator::Configuration)
#       3    1.2%    0.2%  v8::Isolate::SuppressMicrotaskExecutionScope::SuppressMicrotaskExecutionScope(v8::Isolate*)
#       3    1.2%    0.2%  _IO_old_init
#       3    1.2%    0.2%  _IO_no_init
#       2    0.8%    0.1%  void v8::internal::LookupIterator::Start<false>()
#       2    0.8%    0.1%  v8::internal::StackFrameIterator::StackFrameIterator(v8::internal::Isolate*)
#       2    0.8%    0.1%  v8::internal::Object::GetProperty(v8::internal::LookupIterator*)
#       2    0.8%    0.1%  v8::internal::Log::MessageBuilder::WriteToLogFile()
#       2    0.8%    0.1%  v8::internal::Isolate::RunMicrotasksInternal()
#       2    0.8%    0.1%  v8::base::Time::ToJsTime() const
#       2    0.8%    0.1%  __GI_mempcpy
#       2    0.8%    0.1%  __GI__IO_file_xsputn
#       2    0.8%    0.1%  _IO_file_write@@GLIBC_2.2
#       1    0.4%    0.1%  v8::internal::VariableProxy::AssignFeedbackVectorSlots(v8::internal::Isolate*, v8::internal::FeedbackVectorSpec*, v8::internal::FeedbackVectorSlotCache*)
#       1    0.4%    0.1%  v8::internal::TemplateHashMapImpl<v8::internal::FreeStoreAllocationPolicy>::LookupOrInsert(void*, unsigned int, v8::internal::FreeStoreAllocationPolicy) [clone .isra.49]
#       1    0.4%    0.1%  v8::internal::StackFrame::GetCallerState(v8::internal::StackFrame::State*) const
#       1    0.4%    0.1%  v8::internal::PropertyHandlerCompiler::CheckPrototypes(v8::internal::Register, v8::internal::Register, v8::internal::Register, v8::internal::Register, v8::internal::Handle<v8::internal::Name>, v8::internal::Label*, v8::internal::PrototypeCheckType, v8::internal::ReturnHolder)
#       1    0.4%    0.1%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseAssignmentExpression(bool, v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.4%    0.1%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseAndClassifyIdentifier(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.4%    0.1%  v8::internal::Map::Reconfigure(v8::internal::Handle<v8::internal::Map>, v8::internal::ElementsKind, int, v8::internal::PropertyKind, v8::internal::PropertyAttributes, v8::internal::Representation, v8::internal::Handle<v8::internal::FieldType>, v8::internal::StoreMode)
#       1    0.4%    0.1%  v8::internal::Malloced::Delete(void*)
#       1    0.4%    0.1%  v8::internal::Logger::CurrentTimeEvent()
#       1    0.4%    0.1%  v8::internal::Log::MessageBuilder::MessageBuilder(v8::internal::Log*)
#       1    0.4%    0.1%  v8::internal::LoadWithVectorDescriptor::VectorRegister()
#       1    0.4%    0.1%  v8::internal::List<v8::internal::HBasicBlock*, v8::internal::ZoneAllocationPolicy>::Add(v8::internal::HBasicBlock* const&, v8::internal::ZoneAllocationPolicy)
#       1    0.4%    0.1%  v8::internal::LAllocator::AllocateRegisters()
#       1    0.4%    0.1%  v8::internal::JSDate::CurrentTimeValue(v8::internal::Isolate*)
#       1    0.4%    0.1%  v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment)
#       1    0.4%    0.1%  v8::internal::HashTable<v8::internal::StringTable, v8::internal::StringTableShape, v8::internal::HashTableKey*>::FindEntry(v8::internal::Isolate*, v8::internal::HashTableKey*)
#       1    0.4%    0.1%  v8::internal::HOptimizedGraphBuilder::TryArgumentsAccess(v8::internal::Property*)
#       1    0.4%    0.1%  v8::internal::HInstruction::InsertAfter(v8::internal::HInstruction*)
#       1    0.4%    0.1%  v8::internal::HArithmeticBinaryOperation::IsDeletable() const
#       1    0.4%    0.1%  v8::internal::GetICCounts(v8::internal::SharedFunctionInfo*, int*, int*, int*, int*, int*)
#       1    0.4%    0.1%  v8::internal::ExternalCallbackScope::~ExternalCallbackScope()
#       1    0.4%    0.1%  v8::internal::AstRawStringInternalizationKey::IsMatch(v8::internal::Object*)
#       1    0.4%    0.1%  v8::internal::AssemblerPositionsRecorder::RecordStatementPosition(int)
#       1    0.4%    0.1%  v8::base::Mutex::Lock()
#       1    0.4%    0.1%  v8::Isolate::RunMicrotasks()
#       1    0.4%    0.1%  node::RunMicrotasks(v8::FunctionCallbackInfo<v8::Value> const&)
#       1    0.4%    0.1%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
#       1    0.4%    0.1%  memcpy_z196
#       1    0.4%    0.1%  cfree
#       1    0.4%    0.1%  _wordcopy_fwd_aligned
#       1    0.4%    0.1%  __clock_gettime
#       1    0.4%    0.1%  __GI___pthread_mutex_unlock
#       1    0.4%    0.1%  __GI___libc_write
#       1    0.4%    0.1%  __GI__IO_do_write
#       1    0.4%    0.1%  _IO_str_init_static_internal
# 
#  [Bottom up (heavy) profile]:
#   Note: percentage shows a share of a particular caller in the total
#   amount of its parent calls.
#   Callers occupying less than 2.0% are not shown.
# 
#    ticks parent  name
#     713   40.1%  /usr/lib64/libc-2.17.so
#     710   99.6%    LazyCompile: *f [eval]:1:11
#     710  100.0%      LazyCompile: ~<anonymous> [eval]:3:33
#     698   98.3%        LazyCompile: *runCallback timers.js:568:21
#     698  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#     698  100.0%            LazyCompile: *processImmediate timers.js:516:26
# 
#     277   15.6%  syscall
# 
#      67    3.8%  UNKNOWN
# 
# 
#     at runTest (/data/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel72-s390x/test/parallel/test-tick-processor.js:64:3)
#     at Object.<anonymous> (/data/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel72-s390x/test/parallel/test-tick-processor.js:46:1)
#     at Module._compile (module.js:560:32)
#     at Object.Module._extensions..js (module.js:569:10)
#     at Module.load (module.js:477:32)
#     at tryModuleLoad (module.js:436:12)
#     at Function.Module._load (module.js:428:3)
#     at Module.runMain (module.js:594:10)
#     at run (bootstrap_node.js:382:7)
#     at startup (bootstrap_node.js:137:9)
  ---
  duration_ms: 9.354

https://ci.nodejs.org/job/node-test-commit-plinux/4161/nodes=ppcle-ubuntu1404/console

Click here for details

not ok 940 parallel/test-tick-processor # TODO : Fix flaky test
# 
# assert.js:85
#   throw new assert.AssertionError({
#   ^
# AssertionError: /Builtin_DateNow/ not matching Statistical profiling result from isolate-0x1003a4f2270-v8.log, (1889 ticks, 34 unaccounted, 0 excluded).
# 
#  [Shared libraries]:
#    ticks  total  nonlib   name
#      45    2.4%          /lib/powerpc64le-linux-gnu/libc-2.19.so
#      12    0.6%          [vdso]
#       1    0.1%          /usr/lib/powerpc64le-linux-gnu/libstdc++.so.6.0.19
# 
#  [JavaScript]:
#    ticks  total  nonlib   name
#       8    0.4%    0.4%  Stub: JSEntryStub
#       5    0.3%    0.3%  Stub: CallApiCallbackStub
#       2    0.1%    0.1%  LazyCompile: *exports.setImmediate timers.js:599:32
#       1    0.1%    0.1%  Stub: FastNewClosureStub
#       1    0.1%    0.1%  Stub: DirectCEntryStub
#       1    0.1%    0.1%  Stub: CEntryStub
#       1    0.1%    0.1%  LazyCompile: tryOnImmediate timers.js:550:24
#       1    0.1%    0.1%  LazyCompile: *runCallback timers.js:568:21
#       1    0.1%    0.1%  LazyCompile: *emitPendingUnhandledRejections internal/process/promises.js:49:42
#       1    0.1%    0.1%  Builtin: JSConstructStubGeneric
#       1    0.1%    0.1%  Builtin: DateNow
# 
#  [C++]:
#    ticks  total  nonlib   name
#    1154   61.1%   63.0%  __write
#     405   21.4%   22.1%  syscall
#      23    1.2%    1.3%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
#      15    0.8%    0.8%  __GI___pthread_mutex_unlock
#       9    0.5%    0.5%  _IO_fwrite
#       8    0.4%    0.4%  uv_run
#       7    0.4%    0.4%  v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
#       7    0.4%    0.4%  __clock_gettime
#       6    0.3%    0.3%  __GI___pthread_mutex_lock
#       5    0.3%    0.3%  v8::Isolate::SuppressMicrotaskExecutionScope::SuppressMicrotaskExecutionScope(v8::Isolate*)
#       5    0.3%    0.3%  _IO_vfprintf
#       4    0.2%    0.2%  v8::base::Thread::GetThreadLocal(int)
#       4    0.2%    0.2%  v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
#       4    0.2%    0.2%  v8::Context::Exit()
#       4    0.2%    0.2%  v8::Context::Enter()
#       4    0.2%    0.2%  uv__io_poll
#       3    0.2%    0.2%  v8::internal::TimerEventScope<v8::internal::TimerEventExecute>::LogTimerEvent(v8::internal::Logger::StartEnd)
#       3    0.2%    0.2%  v8::internal::HandleScope::DeleteExtensions(v8::internal::Isolate*)
#       3    0.2%    0.2%  v8::Isolate::GetCurrentContext()
#       3    0.2%    0.2%  v8::HandleScope::~HandleScope()
#       3    0.2%    0.2%  v8::EscapableHandleScope::EscapableHandleScope(v8::Isolate*)
#       3    0.2%    0.2%  uv__run_idle
#       3    0.2%    0.2%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
#       2    0.1%    0.1%  v8::platform::DefaultPlatform::PumpMessageLoop(v8::Isolate*)
#       2    0.1%    0.1%  v8::internal::TemplateHashMapImpl<v8::internal::FreeStoreAllocationPolicy>::LookupOrInsert(void*, unsigned int, v8::internal::FreeStoreAllocationPolicy) [clone .isra.49]
#       2    0.1%    0.1%  v8::internal::SaveContext::SaveContext(v8::internal::Isolate*)
#       2    0.1%    0.1%  v8::internal::Logger::ApiEntryCall(char const*)
#       2    0.1%    0.1%  v8::internal::Isolate::RunMicrotasks()
#       2    0.1%    0.1%  v8::internal::Isolate::FireBeforeCallEnteredCallback()
#       2    0.1%    0.1%  v8::internal::Assembler::mov(v8::internal::Register, v8::internal::Operand const&)
#       2    0.1%    0.1%  v8::internal::Assembler::RecordRelocInfo(v8::internal::RelocInfo::Mode, long)
#       2    0.1%    0.1%  v8::Function::Call(v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
#       2    0.1%    0.1%  uv__run_prepare
#       2    0.1%    0.1%  uv__hrtime
#       2    0.1%    0.1%  node::StartNodeInstance(void*)
#       2    0.1%    0.1%  node::MakeCallback(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*)
#       2    0.1%    0.1%  node::CheckImmediate(uv_check_s*)
#       2    0.1%    0.1%  do_futex_wait
#       2    0.1%    0.1%  __libc_free
#       2    0.1%    0.1%  _IO_fflush
#       2    0.1%    0.1%  00000758.plt_call.syscall@@GLIBC_2.17
#       2    0.1%    0.1%  00000758.plt_call.pthread_mutex_unlock@@GLIBC_2.17
#       1    0.1%    0.1%  void v8::internal::Scanner::Advance<false, true>()
#       1    0.1%    0.1%  void v8::internal::LookupIterator::Start<false>()
#       1    0.1%    0.1%  void v8::internal::LookupIterator::NextInternal<false>(v8::internal::Map*, v8::internal::JSReceiver*)
#       1    0.1%    0.1%  v8::platform::PumpMessageLoop(v8::Platform*, v8::Isolate*)
#       1    0.1%    0.1%  v8::internal::Zone::~Zone()
#       1    0.1%    0.1%  v8::internal::ThreadId::GetCurrentThreadId()
#       1    0.1%    0.1%  v8::internal::TemplateHashMapImpl<v8::internal::ZoneAllocationPolicy>::PointersMatch(void*, void*)
#       1    0.1%    0.1%  v8::internal::String::CalculateLineEnds(v8::internal::Handle<v8::internal::String>, bool)
#       1    0.1%    0.1%  v8::internal::StoreIC::Store(v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::Object>, v8::internal::Object::StoreFromKeyed)
#       1    0.1%    0.1%  v8::internal::StackFrameIterator::StackFrameIterator(v8::internal::Isolate*)
#       1    0.1%    0.1%  v8::internal::StackFrameIterator::Advance()
#       1    0.1%    0.1%  v8::internal::Script::GetColumnNumber(v8::internal::Handle<v8::internal::Script>, int)
#       1    0.1%    0.1%  v8::internal::Scanner::Scan()
#       1    0.1%    0.1%  v8::internal::SaveContext::~SaveContext()
#       1    0.1%    0.1%  v8::internal::Runtime_KeyedStoreIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
#       1    0.1%    0.1%  v8::internal::RuntimeProfiler::MarkCandidatesForOptimization()
#       1    0.1%    0.1%  v8::internal::PerIsolateAssertScope<(v8::internal::PerIsolateAssertType)1, false>::IsAllowed(v8::internal::Isolate*)
#       1    0.1%    0.1%  v8::internal::PerIsolateAssertScope<(v8::internal::PerIsolateAssertType)0, true>::IsAllowed(v8::internal::Isolate*)
#       1    0.1%    0.1%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseMemberExpression(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.1%    0.1%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseLeftHandSideExpression(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.1%    0.1%  v8::internal::Parser::ParseSubStatement(v8::internal::ZoneList<v8::internal::AstRawString const*>*, v8::internal::AllowLabelledFunctionStatement, bool*)
#       1    0.1%    0.1%  v8::internal::Object::SetProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode, v8::internal::Object::StoreFromKeyed)
#       1    0.1%    0.1%  v8::internal::MacroAssembler::LoadP(v8::internal::Register, v8::internal::MemOperand const&, v8::internal::Register)
#       1    0.1%    0.1%  v8::internal::Logger::CurrentTimeEvent()
#       1    0.1%    0.1%  v8::internal::LInstruction::IsGap() const
#       1    0.1%    0.1%  v8::internal::LChunk::MarkEmptyBlocks()
#       1    0.1%    0.1%  v8::internal::InnerPointerToCodeCache::GetCacheEntry(unsigned char*)
#       1    0.1%    0.1%  v8::internal::Heap::CopyFixedArrayAndGrow(v8::internal::FixedArray*, int, v8::internal::PretenureFlag)
#       1    0.1%    0.1%  v8::internal::Heap::AllocateCode(int, bool)
#       1    0.1%    0.1%  v8::internal::HValue::SetBlock(v8::internal::HBasicBlock*)
#       1    0.1%    0.1%  v8::internal::HContext::opcode() const
#       1    0.1%    0.1%  v8::internal::FixedArray::set(int, v8::internal::Object*)
#       1    0.1%    0.1%  v8::internal::Factory::NewHeapNumber(double, v8::internal::MutableMode, v8::internal::PretenureFlag)
#       1    0.1%    0.1%  v8::internal::ExpressionStatement::Accept(v8::internal::AstVisitor*)
#       1    0.1%    0.1%  v8::internal::AstValueFactory::GetOneByteStringInternal(v8::internal::Vector<unsigned char const>)
#       1    0.1%    0.1%  v8::internal::Assignment::node_type() const
#       1    0.1%    0.1%  v8::internal::Accessors::FunctionLengthGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
#       1    0.1%    0.1%  v8::base::Time::ToJsTime() const
#       1    0.1%    0.1%  v8::base::OS::VSNPrintF(char*, int, char const*, char*)
#       1    0.1%    0.1%  v8::Locker::IsActive()
#       1    0.1%    0.1%  v8::Isolate::RunMicrotasks()
#       1    0.1%    0.1%  v8::EscapableHandleScope::Escape(v8::internal::Object**)
#       1    0.1%    0.1%  node::RunMicrotasks(v8::FunctionCallbackInfo<v8::Value> const&)
#       1    0.1%    0.1%  node::NeedImmediateCallbackGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
#       1    0.1%    0.1%  c32rtomb
#       1    0.1%    0.1%  __libc_malloc
#       1    0.1%    0.1%  _IO_file_xsputn
#       1    0.1%    0.1%  _IO_file_write
#       1    0.1%    0.1%  _IO_do_write
#       1    0.1%    0.1%  _IO_default_xsputn
#       1    0.1%    0.1%  00000758.plt_call.clock_gettime@@GLIBC_2.17
# 
#  [Summary]:
#    ticks  total  nonlib   name
#      23    1.2%    1.3%  JavaScript
#    1774   93.9%   96.9%  C++
#       0    0.0%    0.0%  GC
#      58    3.1%          Shared libraries
#      34    1.8%          Unaccounted
# 
#  [C++ entry points]:
#    ticks    cpp   total   name
#    1153   92.2%   61.0%  __write
#      23    1.8%    1.2%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
#       9    0.7%    0.5%  _IO_fwrite
#       5    0.4%    0.3%  v8::Isolate::SuppressMicrotaskExecutionScope::SuppressMicrotaskExecutionScope(v8::Isolate*)
#       5    0.4%    0.3%  _IO_vfprintf
#       3    0.2%    0.2%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
#       2    0.2%    0.1%  v8::internal::TemplateHashMapImpl<v8::internal::FreeStoreAllocationPolicy>::LookupOrInsert(void*, unsigned int, v8::internal::FreeStoreAllocationPolicy) [clone .isra.49]
#       2    0.2%    0.1%  v8::internal::Assembler::mov(v8::internal::Register, v8::internal::Operand const&)
#       2    0.2%    0.1%  v8::internal::Assembler::RecordRelocInfo(v8::internal::RelocInfo::Mode, long)
#       2    0.2%    0.1%  __libc_free
#       2    0.2%    0.1%  _IO_fflush
#       1    0.1%    0.1%  void v8::internal::Scanner::Advance<false, true>()
#       1    0.1%    0.1%  v8::internal::Zone::~Zone()
#       1    0.1%    0.1%  v8::internal::TemplateHashMapImpl<v8::internal::ZoneAllocationPolicy>::PointersMatch(void*, void*)
#       1    0.1%    0.1%  v8::internal::StoreIC::Store(v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::Object>, v8::internal::Object::StoreFromKeyed)
#       1    0.1%    0.1%  v8::internal::StackFrameIterator::StackFrameIterator(v8::internal::Isolate*)
#       1    0.1%    0.1%  v8::internal::StackFrameIterator::Advance()
#       1    0.1%    0.1%  v8::internal::Script::GetColumnNumber(v8::internal::Handle<v8::internal::Script>, int)
#       1    0.1%    0.1%  v8::internal::Scanner::Scan()
#       1    0.1%    0.1%  v8::internal::Runtime_KeyedStoreIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)
#       1    0.1%    0.1%  v8::internal::RuntimeProfiler::MarkCandidatesForOptimization()
#       1    0.1%    0.1%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseMemberExpression(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.1%    0.1%  v8::internal::Parser::ParseSubStatement(v8::internal::ZoneList<v8::internal::AstRawString const*>*, v8::internal::AllowLabelledFunctionStatement, bool*)
#       1    0.1%    0.1%  v8::internal::Object::SetProperty(v8::internal::LookupIterator*, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode, v8::internal::Object::StoreFromKeyed)
#       1    0.1%    0.1%  v8::internal::MacroAssembler::LoadP(v8::internal::Register, v8::internal::MemOperand const&, v8::internal::Register)
#       1    0.1%    0.1%  v8::internal::Logger::CurrentTimeEvent()
#       1    0.1%    0.1%  v8::internal::LInstruction::IsGap() const
#       1    0.1%    0.1%  v8::internal::LChunk::MarkEmptyBlocks()
#       1    0.1%    0.1%  v8::internal::Isolate::RunMicrotasks()
#       1    0.1%    0.1%  v8::internal::InnerPointerToCodeCache::GetCacheEntry(unsigned char*)
#       1    0.1%    0.1%  v8::internal::Heap::CopyFixedArrayAndGrow(v8::internal::FixedArray*, int, v8::internal::PretenureFlag)
#       1    0.1%    0.1%  v8::internal::Heap::AllocateCode(int, bool)
#       1    0.1%    0.1%  v8::internal::HValue::SetBlock(v8::internal::HBasicBlock*)
#       1    0.1%    0.1%  v8::internal::HContext::opcode() const
#       1    0.1%    0.1%  v8::internal::FixedArray::set(int, v8::internal::Object*)
#       1    0.1%    0.1%  v8::internal::Factory::NewHeapNumber(double, v8::internal::MutableMode, v8::internal::PretenureFlag)
#       1    0.1%    0.1%  v8::internal::ExpressionStatement::Accept(v8::internal::AstVisitor*)
#       1    0.1%    0.1%  v8::internal::AstValueFactory::GetOneByteStringInternal(v8::internal::Vector<unsigned char const>)
#       1    0.1%    0.1%  v8::internal::Assignment::node_type() const
#       1    0.1%    0.1%  v8::internal::Accessors::FunctionLengthGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
#       1    0.1%    0.1%  v8::base::Time::ToJsTime() const
#       1    0.1%    0.1%  v8::base::OS::VSNPrintF(char*, int, char const*, char*)
#       1    0.1%    0.1%  v8::Isolate::RunMicrotasks()
#       1    0.1%    0.1%  node::RunMicrotasks(v8::FunctionCallbackInfo<v8::Value> const&)
#       1    0.1%    0.1%  node::NeedImmediateCallbackGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
#       1    0.1%    0.1%  c32rtomb
#       1    0.1%    0.1%  __libc_malloc
#       1    0.1%    0.1%  __clock_gettime
#       1    0.1%    0.1%  __GI___pthread_mutex_lock
#       1    0.1%    0.1%  _IO_file_xsputn
#       1    0.1%    0.1%  _IO_file_write
#       1    0.1%    0.1%  _IO_do_write
#       1    0.1%    0.1%  _IO_default_xsputn
# 
#  [Bottom up (heavy) profile]:
#   Note: percentage shows a share of a particular caller in the total
#   amount of its parent calls.
#   Callers occupying less than 2.0% are not shown.
# 
#    ticks parent  name
#    1154   61.1%  __write
#    1150   99.7%    LazyCompile: *f [eval]:1:11
#    1150  100.0%      LazyCompile: ~<anonymous> [eval]:3:33
#    1109   96.4%        LazyCompile: *runCallback timers.js:568:21
#    1109  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#    1109  100.0%            LazyCompile: *processImmediate timers.js:516:26
#      41    3.6%        LazyCompile: ~runCallback timers.js:568:21
#      41  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#      39   95.1%            LazyCompile: *processImmediate timers.js:516:26
#       2    4.9%            LazyCompile: ~processImmediate timers.js:516:26
# 
#     405   21.4%  syscall
# 
#      45    2.4%  /lib/powerpc64le-linux-gnu/libc-2.19.so
#      43   95.6%    LazyCompile: *f [eval]:1:11
#      43  100.0%      LazyCompile: ~<anonymous> [eval]:3:33
#      41   95.3%        LazyCompile: *runCallback timers.js:568:21
#      41  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#      41  100.0%            LazyCompile: *processImmediate timers.js:516:26
#       2    4.7%        LazyCompile: ~runCallback timers.js:568:21
#       2  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#       2  100.0%            LazyCompile: *processImmediate timers.js:516:26
#       1    2.2%    LazyCompile: ~startup bootstrap_node.js:12:19
#       1  100.0%      Function: ~<anonymous> bootstrap_node.js:10:10
#       1    2.2%    LazyCompile: ~<anonymous> [eval]:3:33
#       1  100.0%      LazyCompile: ~runCallback timers.js:568:21
#       1  100.0%        LazyCompile: tryOnImmediate timers.js:550:24
#       1  100.0%          LazyCompile: *processImmediate timers.js:516:26
# 
# 
#     at runTest (/home/iojs/build/workspace/node-test-commit-plinux/nodes/ppcle-ubuntu1404/test/parallel/test-tick-processor.js:64:3)
#     at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-plinux/nodes/ppcle-ubuntu1404/test/parallel/test-tick-processor.js:46:1)
#     at Module._compile (module.js:560:32)
#     at Object.Module._extensions..js (module.js:569:10)
#     at Module.load (module.js:477:32)
#     at tryModuleLoad (module.js:436:12)
#     at Function.Module._load (module.js:428:3)
#     at Module.runMain (module.js:594:10)
#     at run (bootstrap_node.js:382:7)
#     at startup (bootstrap_node.js:137:9)
  ---
  duration_ms: 10.29

https://ci.nodejs.org/job/node-test-commit-arm/4951/nodes=armv7-wheezy/console

Click here for details

not ok 940 parallel/test-tick-processor # TODO : Fix flaky test
# 
# assert.js:85
#   throw new assert.AssertionError({
#   ^
# AssertionError: /Builtin_DateNow/ not matching Statistical profiling result from isolate-0x1478808-v8.log, (232 ticks, 18 unaccounted, 0 excluded).
# 
#  [Shared libraries]:
#    ticks  total  nonlib   name
#      10    4.3%          /lib/arm-linux-gnueabihf/librt-2.13.so
#       1    0.4%          /lib/arm-linux-gnueabihf/libgcc_s.so.1
#       1    0.4%          /lib/arm-linux-gnueabihf/libc-2.13.so
# 
#  [JavaScript]:
#    ticks  total  nonlib   name
#       3    1.3%    1.4%  Stub: FastNewObjectStub
#       3    1.3%    1.4%  LazyCompile: *exports.setImmediate timers.js:599:32
#       2    0.9%    0.9%  Stub: FastNewClosureStub
#       2    0.9%    0.9%  LazyCompile: *runCallback timers.js:568:21
#       2    0.9%    0.9%  LazyCompile: *processImmediate timers.js:516:26
#       2    0.9%    0.9%  LazyCompile: *_tickCallback internal/process/next_tick.js:87:25
#       1    0.4%    0.5%  Stub: LoadICStub
#       1    0.4%    0.5%  Stub: CallConstructStub
#       1    0.4%    0.5%  Stub: CallApiCallbackStub
#       1    0.4%    0.5%  LazyCompile: tryOnImmediate timers.js:550:24
#       1    0.4%    0.5%  LazyCompile: *f [eval]:1:11
#       1    0.4%    0.5%  Builtin: Call_ReceiverIsNotNullOrUndefined
#       1    0.4%    0.5%  Builtin: ArgumentsAdaptorTrampoline
# 
#  [C++]:
#    ticks  total  nonlib   name
#      51   22.0%   23.2%  write
#      13    5.6%    5.9%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
#       9    3.9%    4.1%  gettimeofday
#       6    2.6%    2.7%  void v8::internal::LookupIterator::NextInternal<false>(v8::internal::Map*, v8::internal::JSReceiver*)
#       6    2.6%    2.7%  v8::internal::LookupIterator::PropertyOrElement(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, bool*, v8::internal::LookupIterator::Configuration)
#       5    2.2%    2.3%  v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
#       4    1.7%    1.8%  v8::internal::Assembler::addrmod1(int, v8::internal::Register, v8::internal::Register, v8::internal::Operand const&)
#       4    1.7%    1.8%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
#       3    1.3%    1.4%  v8::internal::ThreadId::GetCurrentThreadId()
#       3    1.3%    1.4%  v8::EscapableHandleScope::EscapableHandleScope(v8::Isolate*)
#       3    1.3%    1.4%  syscall
#       3    1.3%    1.4%  _IO_vfprintf
#       2    0.9%    0.9%  v8::platform::PumpMessageLoop(v8::Platform*, v8::Isolate*)
#       2    0.9%    0.9%  v8::internal::Runtime::GetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>)
#       2    0.9%    0.9%  v8::internal::Object::GetProperty(v8::internal::LookupIterator*)
#       2    0.9%    0.9%  v8::internal::NameDictionaryBase<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::FindEntry(v8::internal::Handle<v8::internal::Name>)
#       2    0.9%    0.9%  v8::internal::LookupIterator::GetDataValue() const
#       2    0.9%    0.9%  v8::internal::ExternalCallbackScope::ExternalCallbackScope(v8::internal::Isolate*, unsigned char*)
#       2    0.9%    0.9%  v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)
#       2    0.9%    0.9%  v8::Object::Get(v8::Local<v8::Value>)
#       2    0.9%    0.9%  v8::Isolate::GetCurrentContext()
#       2    0.9%    0.9%  v8::HandleScope::HandleScope(v8::Isolate*)
#       2    0.9%    0.9%  v8::Context::Exit()
#       2    0.9%    0.9%  node::NeedImmediateCallbackGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
#       2    0.9%    0.9%  node::MakeCallback(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*)
#       1    0.4%    0.5%  void v8::internal::LookupIterator::Start<false>()
#       1    0.4%    0.5%  v8::platform::DefaultPlatform::PopTaskInMainThreadDelayedQueue(v8::Isolate*)
#       1    0.4%    0.5%  v8::internal::TemplateHashMapImpl<v8::internal::FreeStoreAllocationPolicy>::LookupOrInsert(void*, unsigned int, v8::internal::FreeStoreAllocationPolicy) [clone .isra.47]
#       1    0.4%    0.5%  v8::internal::String::CalculateLineEnds(v8::internal::Handle<v8::internal::String>, bool)
#       1    0.4%    0.5%  v8::internal::RuntimeProfiler::MaybeOptimizeFullCodegen(v8::internal::JSFunction*, int, bool)
#       1    0.4%    0.5%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseUnaryExpression(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.4%    0.5%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseMemberExpression(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.4%    0.5%  v8::internal::Parser::ParseStatementListItem(bool*)
#       1    0.4%    0.5%  v8::internal::Parser::ParseFunctionLiteral(v8::internal::AstRawString const*, v8::internal::Scanner::Location, v8::internal::FunctionNameValidity, v8::internal::FunctionKind, int, v8::internal::FunctionLiteral::FunctionType, v8::internal::LanguageMode, bool*)
#       1    0.4%    0.5%  v8::internal::Object::GetPropertyWithAccessor(v8::internal::LookupIterator*)
#       1    0.4%    0.5%  v8::internal::Map::WeakCellForMap(v8::internal::Handle<v8::internal::Map>)
#       1    0.4%    0.5%  v8::internal::LookupIterator::State v8::internal::LookupIterator::LookupInRegularHolder<false>(v8::internal::Map*, v8::internal::JSReceiver*) [clone .part.111]
#       1    0.4%    0.5%  v8::internal::LookupIterator::PrepareTransitionToDataProperty(v8::internal::Handle<v8::internal::JSObject>, v8::internal::Handle<v8::internal::Object>, v8::internal::PropertyAttributes, v8::internal::Object::StoreFromKeyed)
#       1    0.4%    0.5%  v8::internal::LookupIterator::GetAccessors() const
#       1    0.4%    0.5%  v8::internal::Logger::ApiEntryCall(char const*)
#       1    0.4%    0.5%  v8::internal::LCodeGen::WriteTranslation(v8::internal::LEnvironment*, v8::internal::Translation*)
#       1    0.4%    0.5%  v8::internal::LAllocator::TraceAlloc(char const*, ...)
#       1    0.4%    0.5%  v8::internal::Isolate::RunMicrotasksInternal()
#       1    0.4%    0.5%  v8::internal::Isolate::FireBeforeCallEnteredCallback()
#       1    0.4%    0.5%  v8::internal::Heap::AllocateTransitionArray(int)
#       1    0.4%    0.5%  v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment)
#       1    0.4%    0.5%  v8::internal::HandleScope::DeleteExtensions(v8::internal::Isolate*)
#       1    0.4%    0.5%  v8::internal::Factory::NewHeapNumber(double, v8::internal::MutableMode, v8::internal::PretenureFlag)
#       1    0.4%    0.5%  v8::internal::Deserializer::ReadObject(int, v8::internal::Object**)
#       1    0.4%    0.5%  v8::internal::DescriptorArray::Append(v8::internal::Descriptor*)
#       1    0.4%    0.5%  v8::internal::Deoptimizer::TableEntryGenerator::Generate()
#       1    0.4%    0.5%  v8::internal::CompareOperation::IsLiteralCompareTypeof(v8::internal::Expression**, v8::internal::Handle<v8::internal::String>*)
#       1    0.4%    0.5%  v8::internal::Assembler::addrmod2(int, v8::internal::Register, v8::internal::MemOperand const&)
#       1    0.4%    0.5%  v8::internal::Assembler::CheckBuffer()
#       1    0.4%    0.5%  v8::Value::IsFunction() const
#       1    0.4%    0.5%  v8::Object::Get(v8::Local<v8::Context>, v8::Local<v8::Value>)
#       1    0.4%    0.5%  v8::HandleScope::~HandleScope()
#       1    0.4%    0.5%  v8::Function::Call(v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
#       1    0.4%    0.5%  v8::(anonymous namespace)::CallDepthScope::~CallDepthScope()
#       1    0.4%    0.5%  uv_run
#       1    0.4%    0.5%  uv__run_check
#       1    0.4%    0.5%  memset
#       1    0.4%    0.5%  fwrite
#       1    0.4%    0.5%  floor
#       1    0.4%    0.5%  __pthread_mutex_unlock_usercnt
#       1    0.4%    0.5%  __pthread_mutex_lock
#       1    0.4%    0.5%  __pthread_getspecific
#       1    0.4%    0.5%  __printf_fp
#       1    0.4%    0.5%  __errno_location
#       1    0.4%    0.5%  _IO_file_sync
# 
#  [Summary]:
#    ticks  total  nonlib   name
#      21    9.1%    9.5%  JavaScript
#     181   78.0%   82.3%  C++
#       2    0.9%    0.9%  GC
#      12    5.2%          Shared libraries
#      18    7.8%          Unaccounted
# 
#  [C++ entry points]:
#    ticks    cpp   total   name
#      49   42.2%   21.1%  write
#      13   11.2%    5.6%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
#       9    7.8%    3.9%  gettimeofday
#       4    3.4%    1.7%  v8::internal::LookupIterator::PropertyOrElement(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, bool*, v8::internal::LookupIterator::Configuration)
#       4    3.4%    1.7%  v8::internal::Assembler::addrmod1(int, v8::internal::Register, v8::internal::Register, v8::internal::Operand const&)
#       4    3.4%    1.7%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
#       3    2.6%    1.3%  _IO_vfprintf
#       2    1.7%    0.9%  v8::internal::ExternalCallbackScope::ExternalCallbackScope(v8::internal::Isolate*, unsigned char*)
#       2    1.7%    0.9%  node::NeedImmediateCallbackGetter(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&)
#       1    0.9%    0.4%  void v8::internal::LookupIterator::Start<false>()
#       1    0.9%    0.4%  v8::internal::TemplateHashMapImpl<v8::internal::FreeStoreAllocationPolicy>::LookupOrInsert(void*, unsigned int, v8::internal::FreeStoreAllocationPolicy) [clone .isra.47]
#       1    0.9%    0.4%  v8::internal::String::CalculateLineEnds(v8::internal::Handle<v8::internal::String>, bool)
#       1    0.9%    0.4%  v8::internal::RuntimeProfiler::MaybeOptimizeFullCodegen(v8::internal::JSFunction*, int, bool)
#       1    0.9%    0.4%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseUnaryExpression(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.9%    0.4%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseMemberExpression(v8::internal::ExpressionClassifier<v8::internal::ParserTraits>*, bool*)
#       1    0.9%    0.4%  v8::internal::Parser::ParseStatementListItem(bool*)
#       1    0.9%    0.4%  v8::internal::Parser::ParseFunctionLiteral(v8::internal::AstRawString const*, v8::internal::Scanner::Location, v8::internal::FunctionNameValidity, v8::internal::FunctionKind, int, v8::internal::FunctionLiteral::FunctionType, v8::internal::LanguageMode, bool*)
#       1    0.9%    0.4%  v8::internal::Object::GetPropertyWithAccessor(v8::internal::LookupIterator*)
#       1    0.9%    0.4%  v8::internal::Object::GetProperty(v8::internal::LookupIterator*)
#       1    0.9%    0.4%  v8::internal::NameDictionaryBase<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::FindEntry(v8::internal::Handle<v8::internal::Name>)
#       1    0.9%    0.4%  v8::internal::Map::WeakCellForMap(v8::internal::Handle<v8::internal::Map>)
#       1    0.9%    0.4%  v8::internal::LookupIterator::GetAccessors() const
#       1    0.9%    0.4%  v8::internal::LCodeGen::WriteTranslation(v8::internal::LEnvironment*, v8::internal::Translation*)
#       1    0.9%    0.4%  v8::internal::LAllocator::TraceAlloc(char const*, ...)
#       1    0.9%    0.4%  v8::internal::Heap::AllocateTransitionArray(int)
#       1    0.9%    0.4%  v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment)
#       1    0.9%    0.4%  v8::internal::Factory::NewHeapNumber(double, v8::internal::MutableMode, v8::internal::PretenureFlag)
#       1    0.9%    0.4%  v8::internal::DescriptorArray::Append(v8::internal::Descriptor*)
#       1    0.9%    0.4%  v8::internal::CompareOperation::IsLiteralCompareTypeof(v8::internal::Expression**, v8::internal::Handle<v8::internal::String>*)
#       1    0.9%    0.4%  v8::internal::Assembler::addrmod2(int, v8::internal::Register, v8::internal::MemOperand const&)
#       1    0.9%    0.4%  v8::internal::Assembler::CheckBuffer()
#       1    0.9%    0.4%  fwrite
#       1    0.9%    0.4%  floor
#       1    0.9%    0.4%  __errno_location
#       1    0.9%    0.4%  _IO_file_sync
# 
#  [Bottom up (heavy) profile]:
#   Note: percentage shows a share of a particular caller in the total
#   amount of its parent calls.
#   Callers occupying less than 2.0% are not shown.
# 
#    ticks parent  name
#      51   22.0%  write
#      48   94.1%    LazyCompile: *f [eval]:1:11
#      48  100.0%      LazyCompile: ~<anonymous> [eval]:3:33
#      31   64.6%        LazyCompile: *runCallback timers.js:568:21
#      31  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#      31  100.0%            LazyCompile: *processImmediate timers.js:516:26
#      17   35.4%        LazyCompile: ~runCallback timers.js:568:21
#      17  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#      16   94.1%            LazyCompile: *processImmediate timers.js:516:26
#       1    5.9%            LazyCompile: ~processImmediate timers.js:516:26
# 
#      18    7.8%  UNKNOWN
# 
#      13    5.6%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
#      13  100.0%    LazyCompile: ~runInThisContext bootstrap_node.js:391:28
#      13  100.0%      LazyCompile: NativeModule.compile bootstrap_node.js:473:44
#      13  100.0%        LazyCompile: ~NativeModule.require bootstrap_node.js:407:34
#       3   23.1%          Function: ~<anonymous> module.js:1:11
#       3  100.0%            LazyCompile: NativeModule.compile bootstrap_node.js:473:44
#       3  100.0%              LazyCompile: ~NativeModule.require bootstrap_node.js:407:34
#       3  100.0%                LazyCompile: ~evalScript bootstrap_node.js:324:22
#       3  100.0%                  LazyCompile: ~run bootstrap_node.js:109:13
#       3  100.0%                    LazyCompile: ~run bootstrap_node.js:363:15
#       3  100.0%                      LazyCompile: ~startup bootstrap_node.js:12:19
#       2   15.4%          LazyCompile: ~startup bootstrap_node.js:12:19
#       2  100.0%            Function: ~<anonymous> bootstrap_node.js:10:10
#       1    7.7%          LazyCompile: ~setupGlobalVariables bootstrap_node.js:190:32
#       1  100.0%            LazyCompile: ~startup bootstrap_node.js:12:19
#       1  100.0%              Function: ~<anonymous> bootstrap_node.js:10:10
#       1    7.7%          LazyCompile: ~setupGlobalTimeouts bootstrap_node.js:218:31
#       1  100.0%            LazyCompile: ~startup bootstrap_node.js:12:19
#       1  100.0%              Function: ~<anonymous> bootstrap_node.js:10:10
#       1    7.7%          LazyCompile: ~get bootstrap_node.js:240:20
#       1  100.0%            Stub: CEntryStub
#       1  100.0%              LazyCompile: ~<anonymous> bootstrap_node.js:344:30
#       1  100.0%                LazyCompile: ~_combinedTickCallback internal/process/next_tick.js:65:33
#       1  100.0%                  LazyCompile: ~_tickCallback internal/process/next_tick.js:87:25
#       1    7.7%          LazyCompile: ~evalScript bootstrap_node.js:324:22
#       1  100.0%            LazyCompile: ~run bootstrap_node.js:109:13
#       1  100.0%              LazyCompile: ~run bootstrap_node.js:363:15
#       1  100.0%                LazyCompile: ~startup bootstrap_node.js:12:19
#       1  100.0%                  Function: ~<anonymous> bootstrap_node.js:10:10
#       1    7.7%          LazyCompile: ~createWritableStdioStream internal/process/stdio.js:134:35
#       1  100.0%            LazyCompile: ~getStdout internal/process/stdio.js:8:21
#       1  100.0%              Stub: CEntryStub
#       1  100.0%                Function: ~<anonymous> console.js:1:11
#       1  100.0%                  LazyCompile: NativeModule.compile bootstrap_node.js:473:44
#       1  100.0%                    LazyCompile: ~NativeModule.require bootstrap_node.js:407:34
#       1  100.0%                      LazyCompile: ~get bootstrap_node.js:240:20
#       1    7.7%          Function: ~<anonymous> util.js:1:11
#       1  100.0%            LazyCompile: NativeModule.compile bootstrap_node.js:473:44
#       1  100.0%              LazyCompile: ~NativeModule.require bootstrap_node.js:407:34
#       1  100.0%                LazyCompile: ~setupGlobalVariables bootstrap_node.js:190:32
#       1  100.0%                  LazyCompile: ~startup bootstrap_node.js:12:19
#       1  100.0%                    Function: ~<anonymous> bootstrap_node.js:10:10
#       1    7.7%          Function: ~<anonymous> stream.js:1:11
#       1  100.0%            LazyCompile: NativeModule.compile bootstrap_node.js:473:44
#       1  100.0%              LazyCompile: ~NativeModule.require bootstrap_node.js:407:34
#       1  100.0%                Function: ~<anonymous> fs.js:1:11
#       1  100.0%                  LazyCompile: NativeModule.compile bootstrap_node.js:473:44
#       1  100.0%                    LazyCompile: ~NativeModule.require bootstrap_node.js:407:34
#       1  100.0%                      Function: ~<anonymous> module.js:1:11
#       1    7.7%          Function: ~<anonymous> fs.js:1:11
#       1  100.0%            LazyCompile: NativeModule.compile bootstrap_node.js:473:44
#       1  100.0%              LazyCompile: ~NativeModule.require bootstrap_node.js:407:34
#       1  100.0%                Function: ~<anonymous> module.js:1:11
#       1  100.0%                  LazyCompile: NativeModule.compile bootstrap_node.js:473:44
#       1  100.0%                    LazyCompile: ~NativeModule.require bootstrap_node.js:407:34
#       1  100.0%                      LazyCompile: ~evalScript bootstrap_node.js:324:22
# 
#      10    4.3%  /lib/arm-linux-gnueabihf/librt-2.13.so
#       2   20.0%    LazyCompile: *f [eval]:1:11
#       2  100.0%      LazyCompile: ~<anonymous> [eval]:3:33
#       2  100.0%        LazyCompile: *runCallback timers.js:568:21
#       2  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#       2  100.0%            LazyCompile: *processImmediate timers.js:516:26
#       1   10.0%    LazyCompile: formatValue util.js:313:21
#       1  100.0%      LazyCompile: ~inspect util.js:181:17
#       1  100.0%        LazyCompile: ~exports.format util.js:80:26
#       1  100.0%          LazyCompile: ~Console.log console.js:42:33
#       1  100.0%            LazyCompile: ~<anonymous> bootstrap_node.js:344:30
#       1  100.0%              LazyCompile: ~_combinedTickCallback internal/process/next_tick.js:65:33
#       1  100.0%                LazyCompile: ~_tickCallback internal/process/next_tick.js:87:25
# 
#       9    3.9%  gettimeofday
#       9  100.0%    LazyCompile: *f [eval]:1:11
#       9  100.0%      LazyCompile: ~<anonymous> [eval]:3:33
#       6   66.7%        LazyCompile: *runCallback timers.js:568:21
#       6  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#       6  100.0%            LazyCompile: *processImmediate timers.js:516:26
#       3   33.3%        LazyCompile: ~runCallback timers.js:568:21
#       3  100.0%          LazyCompile: tryOnImmediate timers.js:550:24
#       3  100.0%            LazyCompile: *processImmediate timers.js:516:26
# 
#       6    2.6%  void v8::internal::LookupIterator::NextInternal<false>(v8::internal::Map*, v8::internal::JSReceiver*)
# 
#       6    2.6%  v8::internal::LookupIterator::PropertyOrElement(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, bool*, v8::internal::LookupIterator::Configuration)
#       4   66.7%    LazyCompile: *exports.setImmediate timers.js:599:32
#       4  100.0%      LazyCompile: *f [eval]:1:11
#       4  100.0%        LazyCompile: ~<anonymous> [eval]:3:33
#       2   50.0%          LazyCompile: ~runCallback timers.js:568:21
#       2  100.0%            LazyCompile: tryOnImmediate timers.js:550:24
#       2  100.0%              LazyCompile: *processImmediate timers.js:516:26
#       2   50.0%          LazyCompile: *runCallback timers.js:568:21
#       2  100.0%            LazyCompile: tryOnImmediate timers.js:550:24
#       2  100.0%              LazyCompile: *processImmediate timers.js:516:26
# 
#       5    2.2%  v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
# 
# 
#     at runTest (/home/iojs/build/workspace/node-test-commit-arm/nodes/armv7-wheezy/test/parallel/test-tick-processor.js:64:3)
#     at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-arm/nodes/armv7-wheezy/test/parallel/test-tick-processor.js:46:1)
#     at Module._compile (module.js:560:32)
#     at Object.Module._extensions..js (module.js:569:10)
#     at Module.load (module.js:477:32)
#     at tryModuleLoad (module.js:436:12)
#     at Function.Module._load (module.js:428:3)
#     at Module.runMain (module.js:594:10)
#     at run (bootstrap_node.js:382:7)
#     at startup (bootstrap_node.js:137:9)
  ---
  duration_ms: 25.327

indutny · 2016-09-14T00:47:12Z

@Trott let's revert the test changes from #8480 , if it gives troubles. It is not the most important part of it.

matthewloring · 2016-09-14T17:18:23Z

The likelihood that the test will pass is proportional to the amount of time the test function spends with the Date.now() builtin frame on the stack. We can decrease the flake here by picking a more computationally expensive builtin or running the test for longer. It would be good to leave the test there in some form if possible.

ofrobots · 2016-09-14T17:26:08Z

Perhaps we can add a computationally intensive built-in for the express purpose of being able to test that it shows up on the stack. WDYT?

Trott · 2016-09-14T18:09:12Z

I also wonder if we should split this into three separate tests so that:

we can more easily track which test case is failing/flaky at any point in time
we avoid any possibility of one test case having side effects on another test case (I'm not sure that's possible with this test but it won't hurt to split them out)
allow us to experiment with much longer running test cases that may be more reliable but might time out if all are included in a single test file

indutny · 2016-09-14T22:47:37Z

I was thinking about it recently. What if we would wait until the symbol will appear in the profile log?

indutny · 2016-09-14T22:49:15Z

(Not that it is going to be trivial, though. It will involve finding the symbol's address in the output of nm, and matching this address in profiler ticks)

Wait for a sought-for symbol to appear instead of just hard-killing subprocesses at 2s timeout. Fix: nodejs#4427

Trott · 2016-09-14T23:49:00Z

I'm going to remove the windows label from this, as we're seeing failures on lots of platforms, and I'm going to add the help wanted and v8 labels. Feel free to adjust if you think any of those changes could be better.

Trott · 2016-09-14T23:50:21Z

Removing help wanted because looks like we have a PR. :-D

Wait for a sought-for symbol to appear instead of just hard-killing subprocesses at 2s timeout. Fix: #4427 PR-URL: #8542 Reviewed-By: Rich Trott <[email protected]>

refack · 2017-07-31T12:50:24Z

Just spotted on armv7-wheezy:

not ok 877 parallel/test-tick-processor # TODO : Fix flaky test
  ---
  duration_ms: 26.777
  severity: flaky
  stack: |-
    
    assert.js:81
      throw new assert.AssertionError({
      ^
    AssertionError: /Runtime_DateCurrentTime/ not matching Statistical profiling result from isolate-0xbca860-v8.log, (248 ticks, 0 unaccounted, 0 excluded).
    
     [Shared libraries]:
       ticks  total  nonlib   name
         16    6.5%          /lib/arm-linux-gnueabihf/librt-2.13.so
          4    1.6%          /lib/arm-linux-gnueabihf/libc-2.13.so
          2    0.8%          3880e000-3880f000
          2    0.8%          /lib/arm-linux-gnueabihf/libgcc_s.so.1
          1    0.4%          21cc4000-21cc5000
    
     [JavaScript]:
       ticks  total  nonlib   name
          5    2.0%    2.2%  LazyCompile: *exports.setImmediate timers.js:433:32
          3    1.2%    1.3%  Stub: CallICStub(args(0), METHOD, 
          3    1.2%    1.3%  LazyCompile: *_tickCallback node.js:405:27
          2    0.8%    0.9%  Stub: LoadICTrampolineStub
          2    0.8%    0.9%  Stub: CEntryStub
          1    0.4%    0.4%  Stub: FastNewClosureStub
          1    0.4%    0.4%  Stub: DirectCEntryStub
          1    0.4%    0.4%  Stub: CallICStub(args(1), METHOD, 
          1    0.4%    0.4%  Stub: CallApiAccessorStub
          1    0.4%    0.4%  LazyCompile: *init _linklist.js:3:14
          1    0.4%    0.4%  LazyCompile: *f [eval]:1:11
          1    0.4%    0.4%  Builtin: JSEntryTrampoline
    
     [C++]:
       ticks  total  nonlib   name
         58   23.4%   26.0%  write
         11    4.4%    4.9%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
          6    2.4%    2.7%  syscall
          6    2.4%    2.7%  gettimeofday
          4    1.6%    1.8%  v8::internal::LookupIterator::Next()
          4    1.6%    1.8%  v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, bool)
          3    1.2%    1.3%  v8::internal::Runtime::GetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode)
          3    1.2%    1.3%  v8::internal::NameDictionaryBase<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::FindEntry(v8::internal::Handle<v8::internal::Name>)
          3    1.2%    1.3%  _init
          3    1.2%    1.3%  _IO_vfprintf
          2    0.8%    0.9%  v8::internal::Scanner::Next()
          2    0.8%    0.9%  v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [clone .constprop.678]
          2    0.8%    0.9%  v8::internal::DescriptorArray** v8::internal::HandleScope::CreateHandle<v8::internal::DescriptorArray>(v8::internal::Isolate*, v8::internal::DescriptorArray*)
          2    0.8%    0.9%  v8::internal::Context::native_context()
          2    0.8%    0.9%  v8::Value::IsObject() const
          2    0.8%    0.9%  v8::EscapableHandleScope::EscapableHandleScope(v8::Isolate*)
          2    0.8%    0.9%  v8::Context::Exit()
          2    0.8%    0.9%  uv__io_poll
          2    0.8%    0.9%  node::NeedImmediateCallbackGetter(v8::Local<v8::String>, v8::PropertyCallbackInfo<v8::Value> const&)
          2    0.8%    0.9%  node::MakeCallback(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*)
          2    0.8%    0.9%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
          2    0.8%    0.9%  fwrite
          2    0.8%    0.9%  __pthread_mutex_lock
          1    0.4%    0.4%  v8::internal::fits_shifter(unsigned int, unsigned int*, unsigned int*, int*) [clone .part.80]
          1    0.4%    0.4%  v8::internal::Zone::New(unsigned int)
          1    0.4%    0.4%  v8::internal::String::CalculateLineEnds(v8::internal::Handle<v8::internal::String>, bool)
          1    0.4%    0.4%  v8::internal::Scope::ResolveVariable(v8::internal::ParseInfo*, v8::internal::VariableProxy*, v8::internal::AstNodeFactory*)
          1    0.4%    0.4%  v8::internal::Scope::LookupLocal(v8::internal::AstRawString const*)
          1    0.4%    0.4%  v8::internal::Scope::Initialize()
          1    0.4%    0.4%  v8::internal::Scanner::ScanIdentifierOrKeyword()
          1    0.4%    0.4%  v8::internal::Scanner::FindSymbol(v8::internal::DuplicateFinder*, int)
          1    0.4%    0.4%  v8::internal::ReturnStatement::Accept(v8::internal::AstVisitor*)
          1    0.4%    0.4%  v8::internal::PropertyCallbackArguments::Call(void (*)(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&), v8::Local<v8::Name>)
          1    0.4%    0.4%  v8::internal::ParserTraits::ShortcutNumericLiteralBinaryExpression(v8::internal::Expression**, v8::internal::Expression*, v8::internal::Token::Value, int, v8::internal::AstNodeFactory*)
          1    0.4%    0.4%  v8::internal::ParserBase<v8::internal::ParserTraits>::ParseMemberExpressionContinuation(v8::internal::Expression*, v8::internal::ExpressionClassifier*, bool*)
          1    0.4%    0.4%  v8::internal::ParserBase<v8::internal::ParserTraits>::Expect(v8::internal::Token::Value, bool*)
          1    0.4%    0.4%  v8::internal::ParserBase<v8::internal::ParserTraits>::BindingPatternUnexpectedToken(v8::internal::ExpressionClassifier*)
          1    0.4%    0.4%  v8::internal::Parser::ParseFunctionDeclaration(v8::internal::ZoneList<v8::internal::AstRawString const*>*, bool*)
          1    0.4%    0.4%  v8::internal::Object::GetPropertyWithAccessor(v8::internal::LookupIterator*, v8::internal::LanguageMode)
          1    0.4%    0.4%  v8::internal::Object::GetProperty(v8::internal::LookupIterator*, v8::internal::LanguageMode)
          1    0.4%    0.4%  v8::internal::MemOperand::MemOperand(v8::internal::Register, int, v8::internal::AddrMode)
          1    0.4%    0.4%  v8::internal::MaybeHandle<v8::internal::Object> v8::internal::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::(anonymous namespace)::BuiltinArguments<(v8::internal::BuiltinExtraArguments)1>&)
          1    0.4%    0.4%  v8::internal::Map::CopyWithField(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::TypeImpl<v8::internal::HeapTypeConfig> >, PropertyAttributes, v8::internal::Representation, v8::internal::TransitionFlag)
          1    0.4%    0.4%  v8::internal::LookupIterator::IsIntegerIndexedExotic(v8::internal::JSReceiver*)
          1    0.4%    0.4%  v8::internal::LookupIterator::GetRoot(v8::internal::Handle<v8::internal::Object>, v8::internal::Isolate*)
          1    0.4%    0.4%  v8::internal::LookupIterator::GetDataValue() const
          1    0.4%    0.4%  v8::internal::LookupIterator::GetAccessors() const
          1    0.4%    0.4%  v8::internal::Log::MessageBuilder::MessageBuilder(v8::internal::Log*)
          1    0.4%    0.4%  v8::internal::Log::MessageBuilder::AppendDetailed(v8::internal::String*, bool)
          1    0.4%    0.4%  v8::internal::Log::MessageBuilder::Append(char)
          1    0.4%    0.4%  v8::internal::LCodeGenBase::GenerateBody()
          1    0.4%    0.4%  v8::internal::LCodeGen::GenerateBodyInstructionPre(v8::internal::LInstruction*)
          1    0.4%    0.4%  v8::internal::LAllocator::Use(v8::internal::LifetimePosition, v8::internal::LifetimePosition, v8::internal::LOperand*, v8::internal::LOperand*)
          1    0.4%    0.4%  v8::internal::LAllocator::ProcessInstructions(v8::internal::HBasicBlock*, v8::internal::BitVector*)
          1    0.4%    0.4%  v8::internal::LAllocator::AddInitialIntervals(v8::internal::HBasicBlock*, v8::internal::BitVector*)
          1    0.4%    0.4%  v8::internal::JSObjectWalkVisitor<v8::internal::AllocationSiteUsageContext>::StructureWalk(v8::internal::Handle<v8::internal::JSObject>)
          1    0.4%    0.4%  v8::internal::Isolate::RunMicrotasks()
          1    0.4%    0.4%  v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationSpace, v8::internal::AllocationAlignment)
          1    0.4%    0.4%  v8::internal::Heap::AllocateOneByteInternalizedString(v8::internal::Vector<unsigned char const>, unsigned int)
          1    0.4%    0.4%  v8::internal::Heap::AllocateJSObjectFromMap(v8::internal::Map*, v8::internal::PretenureFlag, bool, v8::internal::AllocationSite*)
          1    0.4%    0.4%  v8::internal::HashTable<v8::internal::StringTable, v8::internal::StringTableShape, v8::internal::HashTableKey*>::FindEntry(v8::internal::Isolate*, v8::internal::HashTableKey*)
          1    0.4%    0.4%  v8::internal::HandleScope::Extend(v8::internal::Isolate*)
          1    0.4%    0.4%  v8::internal::HandleScope::DeleteExtensions(v8::internal::Isolate*)
          1    0.4%    0.4%  v8::internal::HValue::EmitAtUses()
          1    0.4%    0.4%  v8::internal::HInstructionMap::HInstructionMap(v8::internal::Zone*, v8::internal::HInstructionMap const*)
          1    0.4%    0.4%  v8::internal::FullCodeGenerator::VisitAssignment(v8::internal::Assignment*)
          1    0.4%    0.4%  v8::internal::FullCodeGenerator::Visit(v8::internal::AstNode*)
          1    0.4%    0.4%  v8::internal::FullCodeGenerator::PrepareForBailoutForId(v8::internal::BailoutId, v8::internal::FullCodeGenerator::State)
          1    0.4%    0.4%  v8::internal::Factory::CopyJSObjectWithAllocationSite(v8::internal::Handle<v8::internal::JSObject>, v8::internal::Handle<v8::internal::AllocationSite>)
          1    0.4%    0.4%  v8::internal::DuplicateFinder::BackupKey(v8::internal::Vector<unsigned char const>, bool)
          1    0.4%    0.4%  v8::internal::CompilationPhase::ShouldProduceTraceOutput() const
          1    0.4%    0.4%  v8::internal::CompilationPhase::CompilationPhase(char const*, v8::internal::CompilationInfo*)
          1    0.4%    0.4%  v8::internal::AstValueFactory::NewSmi(int)
          1    0.4%    0.4%  v8::internal::AstRawString::length() const
          1    0.4%    0.4%  v8::internal::AstRawString::Internalize(v8::internal::Isolate*)
          1    0.4%    0.4%  v8::internal::AstNumberingVisitor::VisitProperty(v8::internal::Property*)
          1    0.4%    0.4%  v8::internal::Assembler::ldr(v8::internal::Register, v8::internal::MemOperand const&, v8::internal::Condition)
          1    0.4%    0.4%  v8::internal::Assembler::bind_to(v8::internal::Label*, int)
          1    0.4%    0.4%  v8::internal::ArrayLiteral::BuildConstantElements(v8::internal::Isolate*)
          1    0.4%    0.4%  v8::internal::AllocationSiteUsageContext::ShouldCreateMemento(v8::internal::Handle<v8::internal::JSObject>)
          1    0.4%    0.4%  v8::base::Thread::GetThreadLocal(int)
          1    0.4%    0.4%  v8::Object::Get(v8::Local<v8::Value>)
          1    0.4%    0.4%  v8::Function::Call(v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
          1    0.4%    0.4%  v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
          1    0.4%    0.4%  v8::(anonymous namespace)::CallDepthScope::~CallDepthScope()
          1    0.4%    0.4%  uv_run
          1    0.4%    0.4%  uv__run_check
          1    0.4%    0.4%  std::string::swap(std::string&)
          1    0.4%    0.4%  memset
          1    0.4%    0.4%  floor
          1    0.4%    0.4%  fflush
          1    0.4%    0.4%  cfree
          1    0.4%    0.4%  __pthread_getspecific
          1    0.4%    0.4%  __libc_malloc
          1    0.4%    0.4%  __aeabi_uldivmod
          1    0.4%    0.4%  _IO_file_sync
          1    0.4%    0.4%  _IO_default_xsputn
    
     [Summary]:
       ticks  total  nonlib   name
         22    8.9%    9.9%  JavaScript
        201   81.0%   90.1%  C++
          2    0.8%    0.9%  GC
         25   10.1%          Shared libraries
    
     [C++ entry points]:
       ticks    cpp   total   name
         57   43.5%   23.0%  write
         11    8.4%    4.4%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
          6    4.6%    2.4%  gettimeofday
          3    2.3%    1.2%  v8::internal::Runtime::GetObjectProperty(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::LanguageMode)
          3    2.3%    1.2%  _IO_vfprintf
          2    1.5%    0.8%  v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [clone .constprop.678]
          2    1.5%    0.8%  v8::internal::DescriptorArray** v8::internal::HandleScope::CreateHandle<v8::internal::DescriptorArray>(v8::internal::Isolate*, v8::internal::DescriptorArray*)
          2    1.5%    0.8%  node::NeedImmediateCallbackGetter(v8::Local<v8::String>, v8::PropertyCallbackInfo<v8::Value> const&)
          2    1.5%    0.8%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
          2    1.5%    0.8%  fwrite
          1    0.8%    0.4%  v8::internal::fits_shifter(unsigned int, unsigned int*, unsigned int*, int*) [clone .part.80]
          1    0.8%    0.4%  v8::internal::Zone::New(unsigned int)
          1    0.8%    0.4%  v8::internal::Scanner::FindSymbol(v8::internal::DuplicateFinder*, int)
          1    0.8%    0.4%  v8::internal::ReturnStatement::Accept(v8::internal::AstVisitor*)
          1    0.8%    0.4%  v8::internal::PropertyCallbackArguments::Call(void (*)(v8::Local<v8::Name>, v8::PropertyCallbackInfo<v8::Value> const&), v8::Local<v8::Name>)
          1    0.8%    0.4%  v8::internal::ParserBase<v8::internal::ParserTraits>::Expect(v8::internal::Token::Value, bool*)
          1    0.8%    0.4%  v8::internal::ParserBase<v8::internal::ParserTraits>::BindingPatternUnexpectedToken(v8::internal::ExpressionClassifier*)
          1    0.8%    0.4%  v8::internal::Object::GetPropertyWithAccessor(v8::internal::LookupIterator*, v8::internal::LanguageMode)
          1    0.8%    0.4%  v8::internal::Object::GetProperty(v8::internal::LookupIterator*, v8::internal::LanguageMode)
          1    0.8%    0.4%  v8::internal::MaybeHandle<v8::internal::Object> v8::internal::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::(anonymous namespace)::BuiltinArguments<(v8::internal::BuiltinExtraArguments)1>&)
          1    0.8%    0.4%  v8::internal::Map::CopyWithField(v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::Name>, v8::internal::Handle<v8::internal::TypeImpl<v8::internal::HeapTypeConfig> >, PropertyAttributes, v8::internal::Representation, v8::internal::TransitionFlag)
          1    0.8%    0.4%  v8::internal::LookupIterator::Next()
          1    0.8%    0.4%  v8::internal::LookupIterator::GetRoot(v8::internal::Handle<v8::internal::Object>, v8::internal::Isolate*)
          1    0.8%    0.4%  v8::internal::LookupIterator::GetAccessors() const
          1    0.8%    0.4%  v8::internal::Log::MessageBuilder::MessageBuilder(v8::internal::Log*)
          1    0.8%    0.4%  v8::internal::Log::MessageBuilder::AppendDetailed(v8::internal::String*, bool)
          1    0.8%    0.4%  v8::internal::Log::MessageBuilder::Append(char)
          1    0.8%    0.4%  v8::internal::LCodeGenBase::GenerateBody()
          1    0.8%    0.4%  v8::internal::LAllocator::Use(v8::internal::LifetimePosition, v8::internal::LifetimePosition, v8::internal::LOperand*, v8::internal::LOperand*)
          1    0.8%    0.4%  v8::internal::JSObjectWalkVisitor<v8::internal::AllocationSiteUsageContext>::StructureWalk(v8::internal::Handle<v8::internal::JSObject>)
          1    0.8%    0.4%  v8::internal::Isolate::RunMicrotasks()
          1    0.8%    0.4%  v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationSpace, v8::internal::AllocationAlignment)
          1    0.8%    0.4%  v8::internal::Heap::AllocateJSObjectFromMap(v8::internal::Map*, v8::internal::PretenureFlag, bool, v8::internal::AllocationSite*)
          1    0.8%    0.4%  v8::internal::HashTable<v8::internal::StringTable, v8::internal::StringTableShape, v8::internal::HashTableKey*>::FindEntry(v8::internal::Isolate*, v8::internal::HashTableKey*)
          1    0.8%    0.4%  v8::internal::HValue::EmitAtUses()
          1    0.8%    0.4%  v8::internal::Factory::CopyJSObjectWithAllocationSite(v8::internal::Handle<v8::internal::JSObject>, v8::internal::Handle<v8::internal::AllocationSite>)
          1    0.8%    0.4%  v8::internal::CompilationPhase::ShouldProduceTraceOutput() const
          1    0.8%    0.4%  v8::internal::CompilationPhase::CompilationPhase(char const*, v8::internal::CompilationInfo*)
          1    0.8%    0.4%  v8::internal::AstRawString::Internalize(v8::internal::Isolate*)
          1    0.8%    0.4%  v8::internal::AstNumberingVisitor::VisitProperty(v8::internal::Property*)
          1    0.8%    0.4%  v8::internal::Assembler::ldr(v8::internal::Register, v8::internal::MemOperand const&, v8::internal::Condition)
          1    0.8%    0.4%  v8::internal::Assembler::bind_to(v8::internal::Label*, int)
          1    0.8%    0.4%  v8::internal::ArrayLiteral::BuildConstantElements(v8::internal::Isolate*)
          1    0.8%    0.4%  v8::internal::AllocationSiteUsageContext::ShouldCreateMemento(v8::internal::Handle<v8::internal::JSObject>)
          1    0.8%    0.4%  std::string::swap(std::string&)
          1    0.8%    0.4%  floor
          1    0.8%    0.4%  fflush
          1    0.8%    0.4%  cfree
          1    0.8%    0.4%  __pthread_mutex_lock
          1    0.8%    0.4%  _IO_file_sync
          1    0.8%    0.4%  _IO_default_xsputn
    
     [Bottom up (heavy) profile]:
      Note: percentage shows a share of a particular caller in the total
      amount of its parent calls.
      Callers occupying less than 2.0% are not shown.
    
       ticks parent  name
         58   23.4%  write
         56   96.6%    LazyCompile: *now native date.js:197:17
         56  100.0%      LazyCompile: *f [eval]:1:11
         56  100.0%        LazyCompile: ~<anonymous> [eval]:3:33
         56  100.0%          LazyCompile: processImmediate timers.js:380:26
    
         16    6.5%  /lib/arm-linux-gnueabihf/librt-2.13.so
          6   37.5%    LazyCompile: *now native date.js:197:17
          6  100.0%      LazyCompile: *f [eval]:1:11
          6  100.0%        LazyCompile: ~<anonymous> [eval]:3:33
          6  100.0%          LazyCompile: processImmediate timers.js:380:26
    
         11    4.4%  node::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
         11  100.0%    LazyCompile: ~runInThisContext node.js:939:28
         11  100.0%      LazyCompile: NativeModule.compile node.js:1021:44
         11  100.0%        LazyCompile: NativeModule.require node.js:955:34
          3   27.3%          Function: ~<anonymous> module.js:1:11
          3  100.0%            LazyCompile: NativeModule.compile node.js:1021:44
          3  100.0%              LazyCompile: NativeModule.require node.js:955:34
          3  100.0%                LazyCompile: evalScript node.js:618:22
          3  100.0%                  LazyCompile: ~startup node.js:13:19
          3  100.0%                    Function: ~<anonymous> node.js:10:10
          2   18.2%          LazyCompile: ~createWritableStdioStream node.js:653:37
          2  100.0%            LazyCompile: ~<anonymous> node.js:699:48
          2  100.0%              Function: ~<anonymous> console.js:1:11
          2  100.0%                LazyCompile: NativeModule.compile node.js:1021:44
          2  100.0%                  LazyCompile: NativeModule.require node.js:955:34
          2  100.0%                    LazyCompile: ~<anonymous> node.js:201:48
          2  100.0%                      LazyCompile: <anonymous> node.js:647:30
          1    9.1%          LazyCompile: ~startup.globalVariables node.js:180:37
          1  100.0%            LazyCompile: ~startup node.js:13:19
          1  100.0%              Function: ~<anonymous> node.js:10:10
          1    9.1%          LazyCompile: ~startup.globalTimeouts node.js:190:36
          1  100.0%            LazyCompile: ~startup node.js:13:19
          1  100.0%              Function: ~<anonymous> node.js:10:10
          1    9.1%          LazyCompile: ~startup node.js:13:19
          1  100.0%            Function: ~<anonymous> node.js:10:10
          1    9.1%          Function: ~<anonymous> stream.js:1:11
          1  100.0%            LazyCompile: NativeModule.compile node.js:1021:44
          1  100.0%              LazyCompile: NativeModule.require node.js:955:34
          1  100.0%                Function: ~<anonymous> fs.js:1:11
          1  100.0%                  LazyCompile: NativeModule.compile node.js:1021:44
          1  100.0%                    LazyCompile: NativeModule.require node.js:955:34
          1  100.0%                      Function: ~<anonymous> module.js:1:11
          1    9.1%          Function: ~<anonymous> buffer.js:1:11
          1  100.0%            LazyCompile: NativeModule.compile node.js:1021:44
          1  100.0%              LazyCompile: NativeModule.require node.js:955:34
          1  100.0%                LazyCompile: ~startup.globalVariables node.js:180:37
          1  100.0%                  LazyCompile: ~startup node.js:13:19
          1  100.0%                    Function: ~<anonymous> node.js:10:10
          1    9.1%          Function: ~<anonymous> assert.js:1:11
          1  100.0%            LazyCompile: NativeModule.compile node.js:1021:44
          1  100.0%              LazyCompile: NativeModule.require node.js:955:34
          1  100.0%                Function: ~<anonymous> timers.js:1:11
          1  100.0%                  LazyCompile: NativeModule.compile node.js:1021:44
          1  100.0%                    LazyCompile: NativeModule.require node.js:955:34
          1  100.0%                      LazyCompile: ~startup.globalTimeouts node.js:190:36
    
          6    2.4%  syscall
    
          6    2.4%  gettimeofday
          6  100.0%    LazyCompile: *now native date.js:197:17
          6  100.0%      LazyCompile: *f [eval]:1:11
          6  100.0%        LazyCompile: ~<anonymous> [eval]:3:33
          6  100.0%          LazyCompile: processImmediate timers.js:380:26
    
          5    2.0%  LazyCompile: *exports.setImmediate timers.js:433:32
          5  100.0%    LazyCompile: *f [eval]:1:11
          5  100.0%      LazyCompile: ~<anonymous> [eval]:3:33
          5  100.0%        LazyCompile: processImmediate timers.js:380:26
    
    
        at runTest (/home/iojs/build/workspace/node-test-commit-arm/nodes/armv7-wheezy/test/parallel/test-tick-processor.js:64:3)
        at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-arm/nodes/armv7-wheezy/test/parallel/test-tick-processor.js:46:1)
        at Module._compile (module.js:409:26)
        at Object.Module._extensions..js (module.js:416:10)
        at Module.load (module.js:343:32)
        at Function.Module._load (module.js:300:12)
        at Function.Module.runMain (module.js:441:10)
        at startup (node.js:140:18)
        at node.js:1043:3
  ...

https://ci.nodejs.org/job/node-test-commit-arm/11208/nodes=armv7-wheezy/

Trott · 2017-07-31T13:28:34Z

FWIW, the test is inherently non-deterministic and thus kind of perma-flaky. Ways to make it more robust would be welcome, of course.

Trott added the test Issues and PRs related to the tests. label Dec 26, 2015

Trott mentioned this issue Dec 26, 2015

test: remove unused variables from HTTPS tests #4426

Closed

Trott mentioned this issue Jan 11, 2016

Node.js Testing WG Meeting 2016-Jan-15 nodejs/testing#1

Closed

Trott added a commit to Trott/io.js that referenced this issue Jan 21, 2016

test: mark test-tick-processor flaky

5a589aa

Ref: nodejs#4427

Trott mentioned this issue Jan 21, 2016

test: mark test-tick-processor flaky #4809

Closed

addaleax mentioned this issue May 10, 2016

test/parallel/test-npm-install.js fails (Node 4.4.4) #6648

Closed

Trott added the windows Issues and PRs related to the Windows platform. label Jun 29, 2016

JoeDoyle23 mentioned this issue Jul 9, 2016

test: Fixes test-tick-processor to not hang on Windows #7628

Closed

2 tasks

Trott mentioned this issue Sep 10, 2016

tickprocessor: pass proper arguments to /bin/sh #8480

Closed

4 tasks

indutny added a commit to indutny/io.js that referenced this issue Sep 14, 2016

test: make test-tick-processor.js non-flaky

a4b9b17

Wait for a sought-for symbol to appear instead of just hard-killing subprocesses at 2s timeout. Fix: nodejs#4427

indutny mentioned this issue Sep 14, 2016

test: make test-tick-processor.js non-flaky #8542

Closed

4 tasks

Trott added help wanted Issues that need assistance from volunteers or PRs that need help to proceed. v8 engine Issues and PRs related to the V8 dependency. and removed windows Issues and PRs related to the Windows platform. labels Sep 14, 2016

indutny closed this as completed in 5a17139 Sep 16, 2016

Fishrock123 pushed a commit that referenced this issue Oct 11, 2016

test: make test-tick-processor.js non-flaky

82b7894

Wait for a sought-for symbol to appear instead of just hard-killing subprocesses at 2s timeout. Fix: #4427 PR-URL: #8542 Reviewed-By: Rich Trott <[email protected]>

Investigate flaky test-tick-processor #4427

Investigate flaky test-tick-processor #4427

Comments

Trott commented Dec 26, 2015

Trott commented Dec 26, 2015

jbergstroem commented Dec 26, 2015

Trott commented Dec 26, 2015

Trott commented Dec 26, 2015

joaocgreis commented Dec 28, 2015

Trott commented Dec 30, 2015

joaocgreis commented Dec 30, 2015

Trott commented Jan 1, 2016

Trott commented Jan 2, 2016

Trott commented Jan 2, 2016

matthewloring commented Jan 2, 2016

Trott commented Jan 2, 2016

Trott commented Jan 2, 2016

Trott commented Jan 3, 2016

joaocgreis commented Jan 5, 2016

Trott commented Jan 5, 2016

Trott commented Jan 19, 2016

matthewloring commented Jan 19, 2016

Trott commented Jan 19, 2016

santigimeno commented Jan 21, 2016

Trott commented Jan 21, 2016

santigimeno commented Jan 21, 2016

Trott commented Jan 21, 2016

matthewloring commented Jan 21, 2016

Trott commented Jun 29, 2016

JoeDoyle23 commented Jul 9, 2016 • edited Loading

matthewloring commented Jul 9, 2016

JoeDoyle23 commented Jul 9, 2016

Trott commented Jul 12, 2016

Trott commented Sep 14, 2016

Trott commented Sep 14, 2016

indutny commented Sep 14, 2016

matthewloring commented Sep 14, 2016

ofrobots commented Sep 14, 2016

Trott commented Sep 14, 2016

indutny commented Sep 14, 2016

indutny commented Sep 14, 2016

Trott commented Sep 14, 2016

Trott commented Sep 14, 2016

refack commented Jul 31, 2017 • edited Loading

Trott commented Jul 31, 2017

JoeDoyle23 commented Jul 9, 2016 •

edited

Loading

refack commented Jul 31, 2017 •

edited

Loading