lucasb has quit [Quit: Connection closed for inactivity]
ur5us has quit [Ping timeout: 260 seconds]
ur5us has joined #jruby
ur5us has quit [Ping timeout: 260 seconds]
Elundia has joined #jruby
Elundia has left #jruby ["Closing Window"]
ur5us has joined #jruby
_whitelogger has joined #jruby
ur5us has quit [Ping timeout: 260 seconds]
ur5us has joined #jruby
ur5us has quit [Ping timeout: 260 seconds]
ur5us has joined #jruby
rusk has joined #jruby
rusk has quit [Read error: Connection reset by peer]
rusk has joined #jruby
ur5us has quit [Ping timeout: 260 seconds]
drbobbeaty has joined #jruby
rusk has quit [Read error: Connection reset by peer]
rusk` has joined #jruby
shellac has joined #jruby
<headius[m]> I don't see what's different about those
lucasb has joined #jruby
shellac has quit [Quit: Computer has gone to sleep.]
shellac has joined #jruby
<headius[m]> I would say both should avoid capturing a trace though
<headius[m]> -Xlog.backtraces could turn off backtrace eliding
<headius[m]> or not...it's meant to log the ones that we can't avoid
travis-ci has joined #jruby
<travis-ci> jruby/jruby (test_concurrent_ruby:e3a49b6 by Charles Oliver Nutter): The build has errored. https://travis-ci.org/jruby/jruby/builds/637495967 [149 min 1 sec]
travis-ci has left #jruby [#jruby]
<headius[m]> nooo
<headius[m]> oh just my deleted branch 👍
shellac has quit [Quit: Computer has gone to sleep.]
xardion has quit [Remote host closed the connection]
xardion has joined #jruby
shellac has joined #jruby
shellac has quit [Quit: ["Textual IRC Client: www.textualapp.com"]]
lopex has quit [Ping timeout: 260 seconds]
Iambchop has quit [Ping timeout: 260 seconds]
fidothe has quit [Ping timeout: 252 seconds]
lopex has joined #jruby
fidothe has joined #jruby
Iambchop has joined #jruby
fidothe has quit [Read error: Connection reset by peer]
sagax has quit [Read error: Connection reset by peer]
shellac has joined #jruby
sagax has joined #jruby
<headius[m]> enebo: I'm working on getting instructions to lazily deserialize, which will be useful for AOT but might actually make IR precompiling a win too
<headius[m]> problem I'm having is that I can't defer the the reading of the instructions because there's no length encoded
<headius[m]> I will probably have to change the writing logic to write the instrs to a temporary byte buffer before actually writing to the stream
<headius[m]> that will be additional overhead for writing but perhaps we don't care?
<enebo[m]> ah you mean total byte size of the chunk
<headius[m]> yeah
<enebo[m]> we do not care since it is a side-effect of compilation thread
<headius[m]> it's a little tricky because you have everything behind interfaces
<enebo[m]> or it would be if we had full time serialization on
<headius[m]> I think this should go in the impl of IRWriterEncoder because the IRWriter class can't really control how or when the encoder writes
<enebo[m]> Assuming this makes it super fast :)
<enebo[m]> I doubt it would be a huge extra overhead to writing
<headius[m]> probably not
<enebo[m]> I mean writing to a byte[] and then doing a single write() or something is probably not slower
<enebo[m]> or not very much
<enebo[m]> I don't remember how do we write anyways?
<headius[m]> probably not much slower yeagh
<enebo[m]> the interface design started from the GSOC project. Honestly, it gives us ability to wrapper it (which is only used for logging)
<headius[m]> oh you know what I do see something interesting
<headius[m]> you seem to write everything to a ByteBuffer?
<enebo[m]> If I was to start that from scratch I would probably fixed width bytes and try to use protobufs and also make a binary interpreter
<headius[m]> yeah
<headius[m]> that would be magic
<enebo[m]> It definitely would be faster
<enebo[m]> faster to start executing at least
shellac has quit [Quit: Computer has gone to sleep.]
<enebo[m]> headius: so I think in some sense our two activities do not stomp on each other
<enebo[m]> I am just reducing usage of IRScope within generated bytecode and at runtime
shellac has joined #jruby
<enebo[m]> I may not make it completely eliminated but as I said before I like the notion that IRScope is for "compiler" activities and staticscope is for "runtime" activities
<enebo[m]> the fact that IRScope is referenced from StaticScope is one unknown still but a quick look and main issue I can see if runtime uses IRScope for non local returns
<headius[m]> yeah it makes sense
<enebo[m]> I keep repeating this because it is the exact opposite of how I felt a year ago
<headius[m]> non-local returns have to use dynamic scope
<enebo[m]> I had the intention of IRScope being the only thing but it is obvious in retrospect it has a cost for stuff like this
<headius[m]> or frame
<enebo[m]> It also makes it much easier to just dangle stuff off of IRScope
<enebo[m]> headius: I have not looked at how it is used but noticed it was used
<enebo[m]> I agree though it probably is replaceable
<enebo[m]> heh I used 'was' ... how is that for optimism
<enebo[m]> Ironically I see getFile() as weirder edge case
<headius[m]> hmm I'm really confused by the workflow of the IR writer
<enebo[m]> but that is really only encountered via AOT itself
<headius[m]> it puts the instruction offset into a map right before it encodes the instructions
<headius[m]> but later it needs to write the offset before the instructions
<enebo[m]> ok I think I can explain this :) It has been a long time
<headius[m]> OH
<headius[m]> I think I just got it
<headius[m]> the scope headers actually go at the end of the file
<enebo[m]> The top of the file contains all scopes and each entry needs to know where instrs are
<enebo[m]> or bottom of the file
<headius[m]> end of the file?
<enebo[m]> somewhere is the scope headers and all instrs are just in a section
<headius[m]> ok I think I get it
<enebo[m]> anyways the instrs are not written into the scope header info
<enebo[m]> that is why there is an offset
<headius[m]> that may make this easier then
<headius[m]> I should be able to just add another map of scope's instr length
<enebo[m]> if you add a length to the scope header it can instantly be lazy as long as you keep it open
<headius[m]> yeah
<enebo[m]> "keep it open"
<headius[m]> that's a separate discussion but I was planning to still read into a byte[]
<headius[m]> yeah
<enebo[m]> you actually could keep a map of files to reopen
<headius[m]> I mean these could also be mmap'ed and then they're "open"
<enebo[m]> with that info but obviously try this one first
<enebo[m]> yeah
<headius[m]> reopening is a worry because file may change
<headius[m]> but byte[] is simple to do for now, and then the scope has everything it needs in memory to restore instrs
<enebo[m]> I mean from an appcds perspective you just need to access into "something"
<headius[m]> I will have you review this
shellac has quit [Quit: Computer has gone to sleep.]
<headius[m]> hmm yeah if the bytes are coming out of constant pool they don't necessarily need to be copied into a new byte[]
<headius[m]> but that's opto we can do later
shellac has joined #jruby
<enebo[m]> yeah I guess that was what I meant by 'something'
ur5us has joined #jruby
<enebo[m]> yeah this may work out really well
shellac has quit [Client Quit]
<enebo[m]> I am sure a lion share of original IR persist was loading instrs
<enebo[m]> for an AOT which will not ever call those then that part of the time will disappear
<enebo[m]> StaticScope itself is smaller so if I succeed then it may chip away at that new cost perhaps
<headius[m]> this would only deserialize a tiny part of Rails + deps on boot
<headius[m]> I dunno why we didn't think of this initially
<headius[m]> intrs can be deserialized any time
<enebo[m]> probably the lack of appcds when we originally put most thought into the problem
shellac has joined #jruby
<enebo[m]> after it came into being older thoughts made the idea not as visible
<headius[m]> you basically did the in-memory buffering for me by having headers come at the end of the file
<enebo[m]> I wanted to read scopes without processing the entire file but I wanted scopes to be able to record that value without having to get into seeking or whatnot
<headius[m]> huh this already has a measurably effect on -e 1
<headius[m]> where does IR write by default
<enebo[m]> One thing I don't recall is how it knows to skip to where the scope headers start
<headius[m]> it outputs that offset at the front of the file
<headius[m]> before it dumps the in-memory buffer
<headius[m]> so you basically are doing what I would have had to do by design
<enebo[m]> ah ok that would have been my guess but then I could have just recorded where to store offsets for each scope and seeked there
<enebo[m]> I don't remember but there might have been some benefit to writing in memory and doing a single write
<enebo[m]> It is atomic in the sense it will not generate a partial file
<enebo[m]> but I doubt that was an explicit reason as much as a coincidental benefit
<headius[m]> oh ~/.ir I think?
<enebo[m]> yeah could be...new laptop
<headius[m]> yeah there it is
<headius[m]> yoink
<headius[m]> is there any verification in the reader?
<enebo[m]> no
<headius[m]> none of this is relevant for AOT but if this actually speeds startup we might start doing it by default
<enebo[m]> gem -S list before/after please
<headius[m]> that's just -e 1
<headius[m]> I'll do a couple other commands
<enebo[m]> aha ok initiateNonLocalReturnJump only uses IRScope frmo StaticScope for debugging on a bug
<enebo[m]> headius: if that is not noise that is pretty amazing
<headius[m]> it seems consistent so far
<headius[m]> rails -v numbers are all over the place
<headius[m]> I got both 8s and 5s in repeat runs
<headius[m]> ir.writing went down to 3s and I haven't seen that again
<enebo[m]> mysterious!
<enebo[m]> log exceptions perhaps
<headius[m]> ir.writing.debug and ir.reading.debug aren't outputting anything
<enebo[m]> although why it would sometimes fail is mysterious unless it involves something with multiple threads reading at once or something
<enebo[m]> hmm also mysterious
<headius[m]> oh duh
<headius[m]> have to have both ir.reading and ir.reading.debug
<enebo[m]> JRUBY_OPTS?
<enebo[m]> you using that for Rails?
<headius[m]> I'm just doing -v
<enebo[m]> ok
<headius[m]> ok wtf
<headius[m]> -Xir.writing is consistently fastest
<enebo[m]> well that makes no sense at all unless it prevents JIT and that happens to be faster
<headius[m]> I added gem list and rails -v to gist
<headius[m]> you tell me man, these numbers are wack
<enebo[m]> LOL
<enebo[m]> -Xir.writing is weird to be sure
<headius[m]> I forgot some context on rails -v, refresh
<enebo[m]> how fast is a plain --dev?
<headius[m]> it ranges from 8s to 5s with just --dev
<headius[m]> 8.x to 5.x
<headius[m]> writing is consistently 3.x 😳
<enebo[m]> haha I wonder if it is really executing
<headius[m]> well it prints the version
<headius[m]> it has to at least be running rails command, rubygems to boot rails logic, and the logic to print version
<enebo[m]> does gem list get faster with only write?
<headius[m]> no, slightly slower with writing than without
<headius[m]> seems consistent
<enebo[m]> I don't recall if write verifies a file is up to date in any way
<enebo[m]> Was it a fingerprint?
<headius[m]> I don't recall either
<enebo[m]> That does not explain anything but still if it is SHA1 or something we could timestamp instead to see how much overhead that is
<headius[m]> this is a fresh write though
<enebo[m]> ah so you are nuking ~/.ir also between some runs
<enebo[m]> maybe somehow this works on rails because it starts processing something in parallel?
<headius[m]> this is consistent
<enebo[m]> maybe throwing on JIT thread makes IR processing way faster and it happens to not need those other methods yet so it doesn't blow up
<headius[m]> somehow we're getting a free 2s by enabling IR write
<enebo[m]> disable jit thread
<enebo[m]> If that answers it then that is a shame :)
<headius[m]> threshold=-1 does nothing
<enebo[m]> but ir.writing does use JITCompiler I think for serialization ... if it ignores threshold then it may still be using that thread pool
<headius[m]> does it?
<headius[m]> I thought this was done at load time
<enebo[m]> I may be remembering wrongly
<headius[m]> IRTranslator.execute
ur5us has quit [Ping timeout: 260 seconds]
<headius[m]> if writing is on it appears to just go for it
<enebo[m]> hmm I am there too now
<enebo[m]> yeah it just calls persist
<enebo[m]> and then execute
<headius[m]> and this is after load+parse+compile
<enebo[m]> what is persist write has a bug and half the loaded files not used happen to throw
<headius[m]> that's the only other read of ir.writing property
<enebo[m]> and that is more overhead
<enebo[m]> not much
<headius[m]> yeah
ur5us has joined #jruby
<enebo[m]> ex.printStackTrace on persist
<enebo[m]> so presumably you would see that
<headius[m]> yeah
<headius[m]> should go straight to stderr
<enebo[m]> I find it impossible to see how this could be that much faster on a single thread
<headius[m]> yeah like way faster
<enebo[m]> I do not think half our startup is parsing
<enebo[m]> part of the whole parse thing is actually registering methods and so forth
<enebo[m]> the execute part mixes into it
<headius[m]> well for rails -v it might be a large part
<headius[m]> parsing + compiling
<enebo[m]> yeah I guess. I mean it still defines a lot of types and methods
<enebo[m]> It must because it takes forever
<enebo[m]> where -v prints in Rails source put a 'gets' and dump with/without
<enebo[m]> See if you have similar numbers of classes/modules
<enebo[m]> ir.write makes no sense bcause it is both reading all the sources of .rb and still deciding to persist them :) No way that can actually be faster
<enebo[m]> We will realize we have been 2x parsing/loading everything for the last 10 years and be happy while crying
<headius[m]> yeah I'm baffled
<headius[m]> wow
<headius[m]> ir.writing.debug needs a non-verbose mode
<headius[m]> and it screwed up my terminal with some ansi color
<enebo[m]> I always write that out to a file
shellac has quit [Quit: Computer has gone to sleep.]
<enebo[m]> The primary debugging was to figure out what operand was missing on encode/decode
<headius[m]> yeah
<headius[m]> maybe I want ir.writing.log
<headius[m]> or something
<enebo[m]> all operands start with ascii char
<headius[m]> I just wanted to know what files were getting written
<enebo[m]> yeah I can only say nuke ~/.ir run the command and see what is there
<enebo[m]> not perfect obviously and it will not tell you what is really in the file
<enebo[m]> although we could probably write a simple print scopes script
<headius[m]> everything seems to be there
<enebo[m]> why underlined?
<headius[m]> Riot
<enebo[m]> That's a riot
<enebo[m]> hey can you try this....JRUBY_OPTS and run echo "exit" | rails c
<headius[m]> yeesh, graalvm starts up slow
<headius[m]> ok
<enebo[m]> I am expecting something is really broken and it will crash because it is just loading a lot more
<headius[m]> oh I need to be in an app
<headius[m]> ok you're probably right
<headius[m]> I'm retesting on proper JVM but I got an NPE booting console with writing on
<enebo[m]> hey I made argumentdescriptor encoder and anonymous descriptors have a name of null
<enebo[m]> what should I encode that as a value?
<enebo[m]> I guess the only limitation is it cannot be a legal variable name
<enebo[m]> $null$?
<enebo[m]> null symbol?
<enebo[m]> KW_REST_ARG_DUMMY = new Symbol(null);
<headius[m]> anonymous descriptors like for def foo(*)?
<enebo[m]> boom
<headius[m]> aha
<headius[m]> I think in JIT I encode it such that if it's anonymous it encodes it as blank
<enebo[m]> so likely it can just return null or bytes
<enebo[m]> encode will just know how to encode null
<headius[m]> like req;foo;req;bar;anonrest;;
<headius[m]> I guess pick whatever name you think will work for yours
<enebo[m]> headius: I don't know there is a difference between "" and null somewhere
<headius[m]> it shouldn't be needed anyway
<headius[m]> hmm ok
<enebo[m]> I would have to dig back into the parser
<enebo[m]> This is something MRI does and I have never tried to change it
<enebo[m]> I have to say spec:compiler is really paying for itself sans having some interals written in Ruby in it
<headius[m]> I tried to keep that minimal but I know what you mean
<enebo[m]> It is not horrible to update that but I half want a Java util for one piece of a method so any internals changes will get flagged by IDE
<headius[m]> I'm going to make this persist empty bytelist for null
<headius[m]> the gymnastics to specially encode null are not worth it right now
<enebo[m]> the tests are great for finding issues though
<headius[m]> yeah I have been using that as my sanity test for a while
<enebo[m]> getBytes() just needs to return null or the bytes and it will just work
<enebo[m]> encode(null) will encode a null internally
<headius[m]> I don't think so
<headius[m]> if I pass null to that it will blow up
<headius[m]> obv
<enebo[m]> ok yeah I just remember it working in other places
<enebo[m]> but I see why that won't work there without some more logic
<headius[m]> and it has to know if it's a normal bytelist or a null bytelist
<headius[m]> too much hassle for the moment
<enebo[m]> put a fixme if you commit that way. because it will make a Symbol("") and if we compare against that final above
<headius[m]> hmm yeah
<enebo[m]> you can try making it "" for the final too
<headius[m]> these special static operands should probably get their own encoding
<headius[m]> if they're going to have nulls and suh
<headius[m]> such
<headius[m]> yeah this blows up
<headius[m]> weird
<enebo[m]> I am just not sure if those mean two things or not
<headius[m]> ok nevermind
<headius[m]> I was trying to mvn from rails
<headius[m]> which blows up in a weirdly spectacular way
shellac has joined #jruby
<enebo[m]> ah yes...I have experienced that as I frequently make an app in jruby dir :)
shellac has quit [Client Quit]
<headius[m]> I think worst case this will have N blank symbols floating around for this KW_REST marker
<headius[m]> they should still compare ok in equals
<headius[m]> hmm but they would also compare to the blank symbol
<headius[m]> ok writing is slower now
<headius[m]> whew
<headius[m]> so I guess the theory was that in rails -v this error was ignored and prevented some subset of files from loading
<headius[m]> that shows you how much time we are wasting loading files though
<headius[m]> getting a buffer underflow though trying to read
<headius[m]> ok another bug...it tries to read a byte[0] and the buffer blows up
<headius[m]> hmm or not
travis-ci has joined #jruby
<travis-ci> jruby/jruby (jit_irscope_removal:ef55e6b by Thomas E. Enebo): The build was broken. https://travis-ci.org/jruby/jruby/builds/637632613 [170 min 10 sec]
travis-ci has left #jruby [#jruby]
<headius[m]> I found a better fix for the symbol thing but still getting an underflow on read
ezzeddine[m] has joined #jruby
* ezzeddine[m] uploaded an image: Screen Shot 2020-01-15 at 1.25.43 PM.png (74KB) < https://matrix.org/_matrix/media/r0/download/matrix.org/qxFjgSvKqgKfePEYjzPvlVIV >
<ezzeddine[m]> data points at 12:50 and 13:50 is when Full GC happens and old gen is getting freed
<ezzeddine[m]> (default sun.rmi.dgc.client.gcInterval=3600000)
<ezzeddine[m]> we didn't have this problem on jruby 1.7 because Full GC happens more frequently
<ezzeddine[m]> same app, jruby 1.7, same jvm options:
* ezzeddine[m] uploaded an image: Screen Shot 2020-01-15 at 1.30.15 PM.png (99KB) < https://matrix.org/_matrix/media/r0/download/matrix.org/UxowfTssACLCgjAxYJIlnKJW >
<ezzeddine[m]> on the second screenshot you can see that Full GC happens more frequently (about every 10 minutes)
<ezzeddine[m]> my question is why jruby 9.2.8.0 does not have these frequent Full GCs whereas jruby 1.7 has them
shellac has joined #jruby
lopex has quit [Quit: Connection closed for inactivity]
<ezzeddine[m]> my theory is jruby 1.7 calls System.GC explicitly where jruby 9.2.8.0 doesn't call System.GC at all
<ezzeddine[m]> can you advise please?
<ezzeddine[m]> here are my JVM flags:
<ezzeddine[m]> CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=8053063680 -XX:+ManagementServer -XX:MaxHeapSize=8053063680 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ThreadStackSize=2048 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
lucasb has quit [Quit: Connection closed for inactivity]
shellac has quit [Quit: Computer has gone to sleep.]
shellac has joined #jruby
<headius[m]> ezzeddine: hello!
<headius[m]> Are these the same JVM version too?
<headius[m]> at a glance it looks like 1.7 is allocating a lot more objects which may trigger full GC to run more often
<headius[m]> but that should be a good thing for 9k
<headius[m]> my first guess would be there's some difference in the JVMs you're running for each
<headius[m]> especially since the full GC on 9k does appear to bring it back to baseline (actually below)
<headius[m]> another possible theory is that we're using more soft or weak references in 9k, which sometimes take a full GC to scrub out
shellac has quit [Quit: Computer has gone to sleep.]
<headius[m]> enebo: I just had a great idea
<headius[m]> spec:compiler tests interpreter, compiled, and compiled with IR
<headius[m]> no reason it couldn't also be repurpose to test IR persistence
<headius[m]> along the way, just serialize the scope, deserialize it, and then proceed
<headius[m]> probably a pretty good guarantee that all constructs would keep working
<headius[m]> (I am fixing persistence bugs so realizing we need testing)
<ezzeddine[m]> headius:
<ezzeddine[m]> * headius: I'm using java 7 on jruby 1.7 and java 8 on jruby 9k
<ezzeddine[m]> any ideas you might suggest to figure out what's going on?
<headius[m]> ok that could certainly make the difference
<headius[m]> I see you specific ParallelGC
<ezzeddine[m]> also I want to mention that this issue is only happening on production under heavy request load
<headius[m]> can you try the JRuby 1.7 app on 8 to rule that out?
<headius[m]> ah so a bit harder to reproduce
<headius[m]> offhand I don't know of an obvious reason why 9k would GC less frequently, except that it's not using as many objects
<headius[m]> the fact that full GC cleans it up makes it a bit of a mystery
<headius[m]> it's possible 1.7 called System.gc but I wouldn't expect so
<ezzeddine[m]> do you want to look at gc.log?
<headius[m]> if you have logs for those time periods that would be helpful
<ezzeddine[m]> yep
<headius[m]> I would also suggest opening an issue now so we can keep track of this
<ezzeddine[m]> ok will do
<headius[m]> I'm poking around a bit to see if there were any big changes to parallel GC in 8
<headius[m]> the other big change in 8 was moving class data to metaspace (no more permgen) so that's certainly a memory effect of some sort
<headius[m]> ezzeddine: I would presume that you see a lot less GC on 9 in general, based on those graphs
<ezzeddine[m]> you mean full gc?
<ezzeddine[m]> or minor gc?
<headius[m]> well hopefully both but definitely full
<headius[m]> your graph seems to use memory more slowly on 9
<ezzeddine[m]> I'll attach gc.log in the issue
ur5us has quit [Ping timeout: 260 seconds]
ur5us has joined #jruby
<headius[m]> ezzeddine: perfect
<headius[m]> enebo: I have rails c writing and reading successfully now
<headius[m]> there were a few other small issues relating to String/Symbol move
<headius[m]> some places still encoded String but decoded Symbol
<headius[m]> this is with my deferred instr decode
<headius[m]> the numbers for reading versus normal seem to be at least equal across the board, and some of these tests are consistently faster
<headius[m]> not by a huge amount but faster
<headius[m]> I'd like to run some profiles of reading and see if there's any low-hanging fruit
ur5us has quit [Ping timeout: 260 seconds]
shellac has joined #jruby