Back to work...JDK8

Charles Oliver Nutter headius at headius.com
Sat Sep 15 15:08:19 PDT 2012 

Ok...I'm starting to poke a bit at JDK8 indy stuff to investigate perf
challenges. This thread will host my observations.

Today I'm monitoring compilation logs, and the odd thing is that no
matter how long I run, PrintCompilation shows no signs of slowing. I
would assume that the compilation logs have a longer tail due to
tiering, but this seems excessive...it's just going on and on and on.

That alone wouldn't worry me unless the JVM guys tell me to worry, but
then I see things like this over and over in the logs:

 782140 40781       4
rubyjit.Rack::Session::Abstract::OptionsHash$$\=\{\}_CBCE967579AE6F1F55C9FF71BA8804158EC7869A648508524::__file__
(10 bytes)
 782144 40666       3
rubyjit.Rack::Session::Abstract::OptionsHash$$\=\{\}_CBCE967579AE6F1F55C9FF71BA8804158EC7869A648508524::__file__
(10 bytes)   made not entrant
 782144 40781       4
rubyjit.Rack::Session::Abstract::OptionsHash$$\=\{\}_CBCE967579AE6F1F55C9FF71BA8804158EC7869A648508524::__file__
(10 bytes)   made not entrant

So this particular piece of code was compiled and then made not
entrant just 4ms later?

I see this over and over and over again...in fact, late in this run,
perhaps 3/4 of the output lines are "made not entrant" or "made
zombie" and it just goes and goes and goes.

Should I be concerned about this?

Here's a dump of just a small portion of PrintCompilation output...


1249422 50524       3
rubyjit.Rack::Request$$port_C30B05D438C56FB2565C807617206F20B98E2FE2648508524::__file__
(8 bytes)
1249424 50525       3
rubyjit.Mime::Mimes$$symbols_100420D4F9BB142680CD7BB51F79045E1B619030648508524::__file__
(8 bytes)
1249810 50526       4
rubyjit.ActiveRecord::LogSubscriber$$runtime=_CD1758211548CDD3492DAD323D979039EA4BC0ED648508524::__file__
(10 bytes)
1249824 50315       3
rubyjit.ActiveRecord::LogSubscriber$$runtime=_CD1758211548CDD3492DAD323D979039EA4BC0ED648508524::__file__
(10 bytes)   made not entrant
1249825 50526       4
rubyjit.ActiveRecord::LogSubscriber$$runtime=_CD1758211548CDD3492DAD323D979039EA4BC0ED648508524::__file__
(10 bytes)   made not entrant
1249969 50527       3
rubyjit.Rack::Request$$GET_D76DBE1FD595925EB82EFFF575EF7260C14C3234648508524::__file__
(10 bytes)
1249979 50528       3
rubyjit.ActionDispatch::Http::ParameterFilter$$compiled_filter_E4708BFBB5F4AD1657B9E83836ACFDC8B379C6DB648508524::__file__
(8 bytes)
1249980 50474       4
rubyjit.#<Class:0x11e31625>$$asset_host_9AFC94A2EF47E84248C0CF85B1FB121C8BE53470648508524::__file__
(15 bytes)   made zombie
1249981 50529       3
rubyjit.ActionDispatch::Http::MimeNegotiation$$accepts_34A6B9527E85807CF247423542D5090EEF79001A648508524::__file__
(8 bytes)
1249986 50530       3
rubyjit.ActionDispatch::Request$$method_EC59F5DFD894E82F7D9FF308054AAFB27CBE06AB648508524::__file__
(8 bytes)
1249990 50305       3
rubyjit.Time$$minus_with_coercion_0F5E81EFFA4D396BAA52CFBEA356B55F32726771648508524::__file__
(10 bytes)   made zombie
1249992 50531       3
rubyjit$ActionController::Instrumentation$$process_action_1910D6D8DE3509AA678DB94D5691451BDEB50046648508524$block_0$RUBY$__file__::call
(13 bytes)
1249998 50532       3
rubyjit.ActionController::Base$$_run_process_action_callbacks_1CEABAA1B8561DBCB7E134F0C024BA9AF08B531A648508524::__file__
(10 bytes)
1250006 50533       3
rubyjit.ActionController::RequestForgeryProtection$$verified_request?_F8254ECDD493CE9EE41068057805A438954180D2648508524::__file__
(8 bytes)
1250010 50106       3
rubyjit.Rack::Cache::CacheControl$$parse_AFED9E9AA448B78AAAB435669B61A6DADA1E75DF648508524::__file__
(10 bytes)   made zombie
1250014 50466       4
rubyjit.#<Module:0x7fe59880>$$locale_595319C157ACD915A0CB1B6E65F30E93C7D07C8C648508524::__file__
(8 bytes)   made zombie
1250016 50534       3
rubyjit.AbstractController::ViewPaths$$formats=_978E9AE3520041B33FAA82EED51F2733EDB234D5648508524::__file__
(10 bytes)
1250018 50460       4
rubyjit.Rack::Cache::CacheControl$$parse_AFED9E9AA448B78AAAB435669B61A6DADA1E75DF648508524::__file__
(10 bytes)   made zombie
1250020 50276       3
rubyjit.Rack::Request$$scheme_C395E273E8CBF823C70EDCBBFC52DF10B6269234648508524::__file__
(8 bytes)   made zombie
1250020 50480       4
rubyjit.Rack::Request$$GET_D76DBE1FD595925EB82EFFF575EF7260C14C3234648508524::__file__
(128 bytes)   made zombie
1250026 50535       3
rubyjit.ActionView::LookupContext$$formats=_23E9B00E4B20D7AA8EB52AB22367DB3D1D37D83B648508524::__file__
(10 bytes)
1250027 50230       3
rubyjit.ActionDispatch::Response$$\=\{\}_599DEC0207F25FEC51ECEBAAB8AD0B113E0E723F648508524::__file__
(10 bytes)   made zombie
1250027 50483   !   4
rubyjit.ActiveRecord::QueryCache::BodyProxy$$close_49A8A831693348CE1AD5FA76FAB8945111B3A66D648508524::chained_0_ensure_1$RUBY$__ensure__
(288 bytes)   made zombie
1250029 50467       4
rubyjit.ActionDispatch::Response$$\=\{\}_599DEC0207F25FEC51ECEBAAB8AD0B113E0E723F648508524::__file__
(10 bytes)   made zombie
1250030 50477       4
rubyjit.ActionDispatch::Cookies::CookieJar$$write_cookie?_9E3227B1C7443C3E1A83A895F8360C3355FBB293648508524::__file__
(78 bytes)   made zombie
1250032 50470       4
rubyjit.Rack::Request$$scheme_C395E273E8CBF823C70EDCBBFC52DF10B6269234648508524::__file__
(8 bytes)   made zombie
1250033 50536       3
rubyjit.ActiveRecord::Railties::ControllerRuntime$$cleanup_view_runtime_456D2875A7FACEE5FA371C02BAC43C3DAAFCBACF648508524::__file__
(10 bytes)
1250034 50469       4
rubyjit.Rack::Request$$host_with_port_1BFCC54D8B1D5C511532C418C20A536207812386648508524::__file__
(8 bytes)   made zombie
1250043 50459       4
rubyjit.Time$$minus_with_coercion_0F5E81EFFA4D396BAA52CFBEA356B55F32726771648508524::__file__
(10 bytes)   made zombie
1250046 50537       3
rubyjit.ActionController::Compatibility$$_normalize_options_7CA3A73C05A0C5FF6C8E1ABE7229208A9112D6C1648508524::__file__
(10 bytes)
1250052 50485   !   4
rubyjit.AbstractController::ViewPaths$$formats=_978E9AE3520041B33FAA82EED51F2733EDB234D5648508524::chained_0_rescue_1$RUBY$SYNTHETIC__file__
(132 bytes)   made zombie
1250056 50540       3
rubyjit.ActiveRecord::LogSubscriber$$runtime=_CD1758211548CDD3492DAD323D979039EA4BC0ED648508524::__file__
(10 bytes)
1250063 50487   !   4
rubyjit.JRuby::Rack::Response$$write_body_07A5A75A2293165FA8C89A81774EA8A99C41BC86648508524::chained_0_ensure_1$RUBY$__ensure__
(121 bytes)   made zombie
1250065 50294       3
rubyjit.#<Class:0x11e31625>$$asset_host_9AFC94A2EF47E84248C0CF85B1FB121C8BE53470648508524::__file__
(15 bytes)   made zombie
1250068 49501       3
rubyjit.#<Module:0x7fe59880>$$locale_595319C157ACD915A0CB1B6E65F30E93C7D07C8C648508524::__file__
(8 bytes)   made zombie
1250071 50457       4
rubyjit.ActionView::LookupContext::Accessors$$formats=_78A37AC39FB37666EC3F9F62B6DB1E3262AFBC3A648508524::__file__
(10 bytes)   made zombie
1250074 50538       3
rubyjit.ActiveSupport::MessageVerifier$$verify_106A8E70B6AB6FB45306BF36007F977DB562F73A648508524::__file__
(10 bytes)
1250082 50361       3
rubyjit.ActiveRecord::Base$$connection_id_9C4C47560320F7F1D34FFF5A842A9C29CCBC6079648508524::__file__
(8 bytes)   made zombie
1250085 50543       4
rubyjit.Rack::ConditionalGet$$call_3F85FD32BC7EF9B82E5CDB21747EEED2925367BF648508524::__file__
(673 bytes)
1250086 50544       4
rubyjit.ActionDispatch::Http::FilterParameters$$filtered_parameters_1269D86467F332ABCD2FF929C617771A476D8240648508524::__file__
(113 bytes)
1250086 50104       3
rubyjit.ActionView::LookupContext::Accessors$$formats=_78A37AC39FB37666EC3F9F62B6DB1E3262AFBC3A648508524::__file__
(10 bytes)   made zombie
1250086 50456       4
rubyjit.AbstractController::ViewPaths$$lookup_context_E57E102D0848EE904F58857E10C71271E59F2F58648508524::__file__
(177 bytes)   made zombie
1250090 50482       4
rubyjit.ActiveSupport::TaggedLogging$$flush_FA9494CB3E6170368159536C8F58BF2FF3C95ECB648508524::__file__
(75 bytes)   made zombie
1250094 50461       4
rubyjit.ActiveRecord::Base$$connection_id_9C4C47560320F7F1D34FFF5A842A9C29CCBC6079648508524::__file__
(8 bytes)   made zombie
1250095 50539       3
rubyjit.ActiveSupport::MessageVerifier$$secure_compare_9370D1984C6C369D6E89440D65546223F1122013648508524::__file__
(12 bytes)
1250103 50479       4
rubyjit.Rack::Cache::Context$$not_modified?_FAD2FE8BEB056EF57D809C367DCC84E53B5A13BE648508524::__file__
(305 bytes)   made zombie
1250103 50543       4
rubyjit.Rack::ConditionalGet$$call_3F85FD32BC7EF9B82E5CDB21747EEED2925367BF648508524::__file__
(673 bytes)   made not entrant
1250107 50462   !   4
rubyjit.ActionDispatch::DebugExceptions$$call_6FBF31DE0A92B21EDCFACD7E5EA4DCB6CAA9F2A3648508524::chained_0_rescue_1$RUBY$SYNTHETIC__file__
(374 bytes)   made zombie
1250109 50231       3
rubyjit.Rack::Request$$host_with_port_1BFCC54D8B1D5C511532C418C20A536207812386648508524::__file__
(8 bytes)   made zombie
1250111 50541       3
rubyjit.JRuby::Rack::Response$$write_body_07A5A75A2293165FA8C89A81774EA8A99C41BC86648508524::__file__
(62 bytes)
1250115 50476       4
rubyjit.ActionDispatch::Response$$initialize_FA88931767B4D2C0D575A7CAF7E60BD0042E4719648508524::__file__
(430 bytes)   made zombie
1250118 50481       4
rubyjit.ActionDispatch::Cookies::SignedCookieJar$$\=\{\}=_198968785F08CF05E82A1B2E5325FFDE0E5FC06E648508524::__file__
(272 bytes)   made zombie
1250122 50478       4
rubyjit.Time$$httpdate_3BE5FAE292F39996D5D83E6ABA3DE418245F893F648508524::__file__
(231 bytes)   made zombie

More information about the mlvm-dev mailing list