is there a way to get the thread state in HHVM?

[lokeshhctm]

I am seeing a lot of time that HHVM is being just hanged. The process is running but it is not accepting any request.
I just want to make sure that thread are busy in doing something or HHVM is going in some state where it stop accepting requests.

When i run top command under linux then i am seeing only one HHVM thread, which should be ideally the master process. but i am not seeing any other HHVM thread. is it a situation where all worker thread are dead for some reason.

[lokeshhctm]

I run GDB and do info thread and found this trace for all threads at that time when HHVM stop accepting requests. Can anybody tell what exactly these threads waiting for:

27 Thread 0x7fd18afff700 (LWP 25751) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
26 Thread 0x7fd18a7ff700 (LWP 25753) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
25 Thread 0x7fd189fff700 (LWP 25755) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
24 Thread 0x7fd1857ff700 (LWP 25760) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
23 Thread 0x7fd17cfff700 (LWP 25761) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
22 Thread 0x7fd1787ff700 (LWP 25762) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
21 Thread 0x7fd177fff700 (LWP 25763) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
20 Thread 0x7fd1777ff700 (LWP 25766) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
19 Thread 0x7fd16abff700 (LWP 25768) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
18 Thread 0x7fd1663ff700 (LWP 25777) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
17 Thread 0x7fd161bff700 (LWP 25784) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
16 Thread 0x7fd15d3ff700 (LWP 25786) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
15 Thread 0x7fd15cbff700 (LWP 25788) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
14 Thread 0x7fd14f7ff700 (LWP 25789) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
13 Thread 0x7fd1503ff700 (LWP 25790) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
12 Thread 0x7fd14efff700 (LWP 25793) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
11 Thread 0x7fd14a7ff700 (LWP 25794) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
10 Thread 0x7fd149fff700 (LWP 25795) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
9 Thread 0x7fd1497ff700 (LWP 25800) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
8 Thread 0x7fd134bff700 (LWP 25806) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
7 Thread 0x7fd1337ff700 (LWP 25807) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
6 Thread 0x7fd132fff700 (LWP 25808) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
5 Thread 0x7fd12e7ff700 (LWP 25813) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
4 Thread 0x7fd125fff700 (LWP 25814) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
3 Thread 0x7fd1257ff700 (LWP 25815) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
2 Thread 0x7fd124fff700 (LWP 25816) __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136

• 1 Thread 0x7fd2b5a80160 (LWP 25362) pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162

[lokeshhctm]

Here is the stack trace of one thread which is being waiting for lock as per logs above:

#0 lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
#1 0x00007fd2af6b1bfa in L_lock_927 () from /lib64/libpthread.so.0
#2 0x00007fd2af6b1bb3 in pthread_mutex_lock (mutex=0x1e91c58) at pthread_mutex_lock.c:101
#3 0x0000000000b15e64 in HPHP::StatCache::statImpl(std::basic_string<char, std::char_traits, std::allocator > const&, stat) ()
#4 0x0000000000aa00df in HPHP::Eval::FileRepository::findFile(HPHP::StringData const, stat) ()
#5 0x0000000000aa0432 in HPHP::Eval::findFileWrapper(HPHP::String const&, void) ()
#6 0x0000000000a84ec2 in HPHP::resolve_include(HPHP::String const&, char const, bool ()(HPHP::String const&, void), void_) ()
#7 0x0000000000a9edf7 in HPHP::Eval::resolveVmInclude(HPHP::StringData_, char const_, stat_) ()
#8 0x0000000000d287c8 in HPHP::VMExecutionContext::lookupPhpFile(HPHP::StringData_, char const_, bool_) ()
#9 0x0000000000d291a4 in HPHP::VMExecutionContext::evalInclude(HPHP::StringData_, HPHP::StringData const_, bool_) ()
#10 0x0000000000d6f139 in void HPHP::VMExecutionContext::dispatchImpl<2>(int) ()
#11 0x0000000000d2a403 in HPHP::VMExecutionContext::dispatchBB() ()
#12 0x0000000000e3c0ce in HPHP::Transl::TranslatorX64::enterTC(unsigned char_, void_) ()
#13 0x0000000000d2a567 in HPHP::VMExecutionContext::enterVMWork(HPHP::ActRec_) ()
#14 0x0000000000d2a758 in HPHP::VMExecutionContext::enterVM(HPHP::TypedValue_, HPHP::ActRec_) ()
#15 0x0000000000d2b2b7 in HPHP::VMExecutionContext::invokeFunc(HPHP::TypedValue_, HPHP::Func const_, HPHP::Array const&, HPHP::ObjectData_, HPHP::Class_, HPHP::VarEnv_, HPHP::StringData_, HPHP::VMExecutionContext::InvokeFlags) ()
#16 0x0000000000d2bfd5 in HPHP::VMExecutionContext::invokeUnit(HPHP::TypedValue_, HPHP::Unit_) ()
#17 0x0000000000a836d7 in HPHP::invoke_file(HPHP::String const&, bool, char const_) ()
#18 0x0000000000a846c2 in HPHP::include_impl_invoke(HPHP::String const&, bool, char const_) ()
#19 0x0000000000af05dc in HPHP::hphp_invoke(HPHP::ExecutionContext_, std::basic_string<char, std::char_traits, std::allocator > const&, bool, HPHP::Array const&, HPHP::VRefParamValue const&, std::basic_string<char, std::char_traits, std::allocator > const&, std::basic_string<char, std::char_traits, std::allocator > const&, bool&, std::basic_string<char, std::char_traits, std::allocator >&, bool, bool, bool) ()
#20 0x0000000000c9b230 in HPHP::HttpRequestHandler::executePHPRequest(HPHP::Transport_, HPHP::RequestURI&, HPHP::SourceRootInfo&, bool) ()
#21 0x0000000000c9ca6c in HPHP::HttpRequestHandler::handleRequest(HPHP::Transport_) ()
#22 0x0000000000f40ce8 in HPHP::LibEventWorker::doJobImpl(boost::shared_ptrHPHP::LibEventJob, bool) ()
#23 0x0000000000f40f5a in HPHP::LibEventWorker::doJob(boost::shared_ptrHPHP::LibEventJob) ()
#24 0x0000000000ca6038 in HPHP::JobQueueWorkerboost::shared_ptr<HPHP::LibEventJob, true, false, HPHP::JobQueueDropVMStack>::start() ()
#25 0x0000000000e83e77 in HPHP::AsyncFuncImpl::threadFuncImpl() ()
#26 0x0000000000e84010 in HPHP::AsyncFuncImpl::ThreadFunc(void_) ()
#27 0x00007fd2af6afc6b in start_thread (arg=0x7fd124fff700) at pthread_create.c:301
#28 0x00007fd2ad8275ed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

[scannell]

Huh. What is the callstack of the first thread that is blocked in pthread_cond_wait? Looks like we have a deadlock somewhere in the stats code. If you look at the code, you'll see that all those threads are doing stats logging.

What is your stat-related configuration in your .hdf file? That would help as well.

[lokeshhctm]

Log {
Level = Error
NoSilencer = true
AlwaysLogUnhandledExceptions = true
RuntimeErrorReportingLevel = 16384
Header = false
HeaderMangle = 0
InjectedStackTrace = true
NativeStackTrace = true
MaxMessagesPerRequest = -1
ApplicationLog = true

# error log settings
UseLogFile = true
UseCronolog = true
File = /mnt/log/hiphop/error_%Y%m%d_%H.log

}

ErrorHandling {
CallUserHandlerOnFatals = true
MaxLoopCount = 0
NoInfiniteLoopDetection = false
NoInfiniteRecursionDetection = false
ThrowBadTypeExceptions = false
ThrowTooManyArguments = false
WarnTooManyArguments = false
ThrowMissingArguments = false
ThrowInvalidArguments = false
EnableHipHopErrors = true
NoticeFrequency = 0
WarningFrequency = 0
AssertActive = false
AssertWarning = false
}

ResourceLimit {
CoreFileSize = 100000000000 # in bytes
MaxSocket = 400000
SocketDefaultTimeout = 5 # in seconds
MaxRSS = 0
MaxRSSPollingCycle = 0 # in seconds, how often to check max memory
DropCacheCycle = 0 # in seconds, how often to drop disk cache
}

Server {
SourceRoot = /var/cake_1.2.0.6311-beta/app/webroot/
RequestTimeoutSeconds = 5
RequestMemoryMaxBytes = -1
DefaultDocument = fam/hiphop.php
Port = 9000
IP = 0.0.0.0
ThreadCount = 40
StatCache = true
AlwaysUseRelativePath = false
RequestInitDocument = /var/cake_1.2.0.6311-beta/app/webroot/openx/www/delivery/startup.php
RequestInitFunction = requestStart
EnableMemoryManager = true
CheckMemory = false
ForceServerNameToHeader = false

    EnableKeepAlive = false
    EnableEarlyFlush = true

    # shutdown options
    GracefulShutdownWait = 0   # in seconds
    HarshShutdown = true
    EvilShutdown = true
    DanglingWait = 0
    MaxPostSize = 8  # in MB
     LibEventSyncSend = true
     ResponseQueueCount = 0
     #SafeFileAccess = true
    APC {
            EnableApc = true
    }

}
Eval {
Jit = true
JitWarmupRequests = 3
EnableObjDestructCall = true
CheckSymLink = true

    }

Http {
DefaultTimeout = 5 # in seconds
SlowQueryThreshold = 3000 # in ms, log slow HTTP requests as errors
}

Preg {
BacktraceLimit = 100000000
RecursionLimit = 100000000
ErrorLog = false
}

Stats = false
Stats {
Web = false
Memory = false
APC = false
APCKey = false
Memcache = false
SQL = false
SlotDuration = 600 # in seconds
MaxSlot = 72 # 10 minutes x 72 = 12 hours
APCSize {
Enable = true
CountPrime = false
Group = false
Individual = false
FetchStats = false
SpecialPrefix {
* = sv:/
}
SpecialMiddle {
* = :sv:/
}
}
}
AdminServer {
Port = 8088
ThreadCount = 1
Password =
}

Debug {
FullBacktrace = true
ServerStackTrace = true
ServerErrorMessage = true
TranslateSource = true

RecordInput = false
ClearInputOnSuccess = true

ProfilerOutputDir = /mnt/log/hiphop/profiler/

CoreDumpEmail = email address

CoreDumpReport = true
CoreDumpReportDirectory = /mnt/log/hiphop/core/

LocalMemcache = false
MemcacheReadOnly = false

}

Above is the configuration i am using. when i make "StatCache = false". then i am not seeing deadlock.

Repo {
Eval {
Mode = local
}
Local {
Path = /mnt/extensions/dev/hiphop-php/local.hhvm.hhbc
}
Central {
Path = /mnt/extensions/dev/hiphop-php/hhvm.hhbc
}
}

[scannell]

When you do see the deadlock, what is the callstack of the thread that is blocked in pthread_cond_wait? (This is the one that is presumably holding the lock all the other threads are waiting upon.)

[ptarjan]

Needs more information