mechanize: loading takes a while

deepj commented 5 years ago

I guess loading mechanize gem taking over 25 ~12 seconds is not good. TruffleRuby 1.0 RC11:

To reproduce:

require 'benchmark'
Benchmark.measure { require 'mechanize' }
=> #<Benchmark::Tms:0x18a38 @cstime=0.0, @cutime=0.0, @label="", @real=12.3722796980001, @stime=0.690929, @total=28.26333, @utime=27.572401>

chrisseaton commented 5 years ago

No that it makes it any better but the relevant time there is real isn't it? At 12 seconds.

deepj commented 5 years ago

Right, I'm sorry of that. It's a half of that ~ 12.5s => real. Still, it's slow. Compare to Ruby 2.5.3

#<Benchmark::Tms:0x00007f8e50357b00 @label="", @real=0.452417999971658, @cstime=0.0, @cutime=0.0, @stime=0.092137, @utime=0.330716, @total=0.42285300000000003>

chrisseaton commented 5 years ago

It only takes 5s for me, compared to 0.4s for MRI. That's still pretty bad but I'm not seeing what you are.

$ time ruby -rmechanize -eexit

Try running with -Xlog.load and you can see it pause a little on a few files while loading, so we'd look at those to see what's going on in them. Maybe it pauses for longer on some of yours?

deepj commented 5 years ago

$ time ruby -rmechanize -eexit
12.50 real        24.71 user         1.40 sys

The time similar to the previous measure.

When I run it as ruby -Xlog.load -rmechanize -eexit. I got this:

[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/patches/rubygems.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/rbconfig.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/compatibility.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/defaults.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/deprecate.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/errors.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/specification.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/version.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/requirement.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/platform.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/patches/rubygems/basic_specification.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/basic_specification.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/stub_specification.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/util/list.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/stringio.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/common.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/rfc2396_parser.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/rfc3986_parser.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/generic.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/ftp.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/http.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/https.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/ldap.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/ldaps.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/uri/mailto.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/exceptions.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/rubygems/defaults/operating_system.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/rubygems/defaults/truffleruby.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/dependency.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/core_ext/kernel_gem.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/core_ext/kernel_require.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/monitor.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/rubygems/gem_dirs_verification.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/path_support.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/version.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/fileutils.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/etc.su
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/truffle/cext.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/truffle/cext_ruby.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/truffle/cext_constants.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/forwardable.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/forwardable/impl.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/mutex_m.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/net-http-digest_auth-1.4.1/lib/net/http/digest_auth.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/cgi.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/cgi/core.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/cgi/cookie.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/cgi/util.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/digest.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/protocol.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/fcntl.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/truffle/ffi/ffi.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/truffle/ffi/ffi_struct.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/socket_options.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/socket_error.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/basic_socket.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/constants.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/addrinfo.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/linger.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/ifaddrs.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/sockaddr.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/sockaddr_in.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/sockaddr_in6.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/sockaddr_un.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/iovec.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/msghdr.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/hostent.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign/servent.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/ipv6.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/ancillary_data.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/foreign.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/error.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/truffle/bsd.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/socket.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/option.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/ancillary_data.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/mri.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/unix_socket.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/unix_server.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/ip_socket.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/udp_socket.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/tcp_socket.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/tcp_server.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/addrinfo.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/socket/ifaddr.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/timeout.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/io/wait.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/zlib.su
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/exceptions.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/header.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/generic_request.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/request.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/requests.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/response.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/responses.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/proxy_delta.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/http/backward.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/securerandom.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/net-http-persistent-3.0.0/lib/net/http/persistent.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/connection_pool-2.2.2/lib/connection_pool.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/connection_pool-2.2.2/lib/connection_pool/version.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/connection_pool-2.2.2/lib/connection_pool/timed_stack.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/connection_pool-2.2.2/lib/connection_pool/monotonic_time.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl.su
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl/bn.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl/pkey.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl/cipher.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl/config.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl/digest.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl/x509.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl/ssl.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl/buffering.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/io/nonblock.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/net-http-persistent-3.0.0/lib/net/http/persistent/connection.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/net-http-persistent-3.0.0/lib/net/http/persistent/pool.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/net-http-persistent-3.0.0/lib/net/http/persistent/timed_stack_multi.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/nokogiri.su
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/version.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/syntax_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/pp.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/pp/node.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/pp/character_data.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/parse_options.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/sax.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/sax/document.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/sax/parser_context.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/sax/parser.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/sax/push_parser.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/searchable.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/node.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/node/save_options.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/attribute_decl.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/element_decl.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/element_content.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/character_data.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/namespace.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/attr.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/dtd.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/cdata.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/text.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/document.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/document_fragment.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/processing_instruction.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/node_set.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/syntax_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/xpath.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/xpath/syntax_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/xpath_context.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/builder.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/reader.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/notation.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/entity_decl.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/entity_reference.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/schema.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xml/relax_ng.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xslt.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/xslt/stylesheet.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/entity_lookup.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/document.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/document_fragment.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/sax/parser_context.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/sax/parser.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/sax/push_parser.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/element_description.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/element_description_defaults.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/decorators/slop.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/css.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/css/node.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/css/xpath_visitor.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/css/parser.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/racc/parser.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/css/parser_extras.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/css/tokenizer.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/strscan.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/css/syntax_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/nokogiri-1.10.1/lib/nokogiri/html/builder.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/pp.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/prettyprint.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/webrick/httputils.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/tempfile.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/tmpdir.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/element_not_found_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/response_read_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/chunked_termination_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/content_type_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/cookie.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/http-cookie-1.0.3/lib/http/cookie.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/http-cookie-1.0.3/lib/http/cookie/version.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/time.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/date.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/date/format.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/domain_name-0.5.20180417/lib/domain_name.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/domain_name-0.5.20180417/lib/domain_name/version.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/domain_name-0.5.20180417/lib/domain_name/punycode.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/domain_name-0.5.20180417/lib/domain_name/etld_data.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/unf-0.1.4/lib/unf.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/unf-0.1.4/lib/unf/version.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/ipaddr.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/http-cookie-1.0.3/lib/http/cookie/ruby_compat.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/cookie_jar.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/http-cookie-1.0.3/lib/http/cookie_jar.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/http-cookie-1.0.3/lib/http/cookie_jar/yaml_saver.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/yaml.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/versions.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych.su
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/syntax_error.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/exception.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/nodes.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/nodes/node.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/class_loader.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/omap.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/set.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/scalar_scanner.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/nodes/stream.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/nodes/document.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/nodes/sequence.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/nodes/scalar.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/nodes/mapping.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/nodes/alias.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/streaming.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/visitors.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/visitors/visitor.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/visitors/to_ruby.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/visitors/emitter.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/visitors/yaml_tree.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/tree_builder.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/handler.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/visitors/json_tree.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/json/ruby_events.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/visitors/depth_first.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/parser.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/coder.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/core_ext.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/deprecated.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/stream.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/json/tree_builder.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/json/yaml_events.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/json/stream.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/psych/handlers/document_stream.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/http-cookie-1.0.3/lib/http/cookie_jar/abstract_saver.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/parser.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/download.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/directory_saver.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/file.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/file_connection.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/file_request.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/file_response.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/element_matcher.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/field.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/button.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/hidden.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/text.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/textarea.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/submit.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/reset.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/file_upload.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/keygen.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/image_button.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/multi_select_list.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/option.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/radio_button.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/check_box.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/form/select_list.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/history.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/http.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/http/agent.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/ntlm-http-0.1.1/lib/net/ntlm.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/base64.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/kconv.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/nkf.su
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/webrobots-0.1.2/lib/webrobots.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/webrobots-0.1.2/lib/webrobots/version.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/webrobots-0.1.2/lib/webrobots/robotstxt.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/net/https.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/webrobots-0.1.2/lib/webrobots/nokogiri.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/http/auth_store.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/http/auth_challenge.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/http/auth_realm.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/http/content_disposition_parser.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/http/www_authenticate_parser.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/image.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/page.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/headers.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/page/image.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/page/label.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/page/link.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/page/base.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/page/frame.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/page/meta_refresh.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/pluggable_parsers.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/file_saver.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/xml_file.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/types.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/type.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/types/cache.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/types/container.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/set.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/types/loader.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-data-3.2018.0812/lib/mime/types/data.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/types/logger.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/logger.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/types/_columnar.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/type/columnar.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/types/registry.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/redirect_limit_reached_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/redirect_not_get_or_head_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/response_code_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/robots_disallowed_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/unauthorized_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/unsupported_scheme_error.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mechanize-2.7.6/lib/mechanize/util.rb

chrisseaton commented 5 years ago

Does it pause on any of those lines for noticeably longer than the others though? Or do they all seem to take about as long? You can hit return a few times when one pauses a bit, for example (sorry I know that's a bit hacky.)

deepj commented 5 years ago

@chrisseaton you're faster than me :) I published the comment above accidentally.

I have some significant pauses on these loads

[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/rubygems/path_support.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/net-http-digest_auth-1.4.1/lib/net/http/digest_auth.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl.rb
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/mri/openssl.su
[ruby] INFO: loading ~/.rubies/truffleruby-1.0.0-rc11/lib/truffle/io/nonblock.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/net-http-persistent-3.0.0/lib/net/http/persistent/connection.rb
[ruby] INFO: loading ~/.gem/truffleruby/2.4.4/gems/mime-types-3.2.2/lib/mime/types/registry.rb

Then there plenty other loads which are not fast like the rest ones.

chrisseaton commented 5 years ago

mime-types-3.2.2/lib/mime/types/registry.rb was my slowest. We can probably set up a test that loads these files without using mechanize in order to reproduce more simply.

deepj commented 5 years ago

I uploaded a video in webm container which would be playable in main browsers supporting WebM.

mechanize.webm.zip

I had to zip it due to Github restrictions.

chrisseaton commented 5 years ago

Ok there's a few things to look at there. We'll get back to this, thanks. Might be lower priority as many of our other open issues are blockers rather than being slow.

eregon commented 5 years ago

One way to measure this conveniently and visualize is jt metrics time:

TRUFFLERUBY_METRICS_REPS=1 AOT_BIN=~/.rubies/truffleruby-native/bin/ruby jt metrics time -Xmetrics.time.parsing.file=true -Xmetrics.time.require=true  --flamegraph --native -rmechanize -e0

which gives: screenshot from 2019-01-27 12-41-04

Download https://gist.github.com/eregon/fc831147c68ff7837528d56015fd3935 and open in a browser for the interactive file. BTW, it takes 4.4s on my laptop with latest master.

I think we should make these metrics & visualization tools available in GraalVM & the standalone, so everyone can run it easily.

deepj commented 5 years ago

A similar issue is with loading net/ssh

oracle / truffleruby

mechanize: loading takes a while #1551