Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Parsing performance #10

Open
tarelli opened this issue Feb 7, 2015 · 4 comments
Open

Parsing performance #10

tarelli opened this issue Feb 7, 2015 · 4 comments
Assignees
@tarelli
Labels
bug

Comments

@tarelli
Copy link
Member

tarelli commented Feb 7, 2015

I was doing some profiling of Geppetto to see where the bulk of the time was spent with NeuroML documents, I found the following:

With the Purkinje cell:

[2015-02-07 15:02:54.637] INFO  http-bio-8080-exec-4         o.geppetto.model.neuroml.services.NeuroMLModelInterpreterService  Parsed NeuroML document of size 1170KB, took 1554ms

With the Auditory cortex model:

[2015-02-07 15:06:10.012] INFO  http-bio-8080-exec-5         o.geppetto.model.neuroml.services.NeuroMLModelInterpreterService  Parsed NeuroML document of size 2287KB, took 19064ms

Auditory is twice the size and takes ten times the time to parse.
Twenty seconds is a LOT (even one second is).

This is the code

            /*
             * NEUROML
             */
            start=System.currentTimeMillis();
            NeuroMLConverter neuromlConverter = new NeuroMLConverter();
            NeuroMLDocument neuroml = neuromlConverter.loadNeuroML(neuromlString);
            _logger.info("Parsed NeuroML document of size "+neuromlString.length()/1024+"KB, took "+(System.currentTimeMillis()-start)+"ms");

Using version 1.4.0. but pretty sure it's the same with any version. This is with single selfcontained neuroml files that contain all the inclusion inside them.
cc @pgleeson @adrianq @borismarin
@tarelli tarelli added the bug label Feb 7, 2015
@tarelli
Copy link
Member Author

tarelli commented Feb 7, 2015

Investigating this, it seems to be related to NeuroML getting LEMS definitons for NeuroML in the one single NeuroML file.

@tarelli tarelli self-assigned this Feb 7, 2015
@borismarin
Copy link
Contributor

Don't know if that helps, but here's the log of my local webserver (hosting the example) when loading ACnet2:

127.0.0.1 - - [07/Feb/2015 22:26:57] "GET /GEPPETTO.xml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:57] "GET /MediumNet.net.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:57] "GET /AMPA_syn.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:57] "GET /AMPA_syn.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:57] "GET /AMPA_syn_inh.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:58] "GET /AMPA_syn_inh.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:58] "GET /bask.cell.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:59] "GET /bask.cell.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:59] "GET /Kdr_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:59] "GET /Kdr_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:26:59] "GET /LeakConductance_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:00] "GET /LeakConductance_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:00] "GET /Na_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:00] "GET /Na_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:00] "GET /Ca_conc.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:01] "GET /Ca_conc.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:01] "GET /Ca_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:01] "GET /Ca_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:01] "GET /GABA_syn.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:02] "GET /GABA_syn.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:02] "GET /GABA_syn_inh.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:02] "GET /GABA_syn_inh.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:02] "GET /Kahp_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:03] "GET /Kahp_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:03] "GET /Kdr_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:04] "GET /Kdr_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:04] "GET /LeakConductance_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:04] "GET /LeakConductance_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:04] "GET /Na_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:05] "GET /Na_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:05] "GET /pyr_4_sym.cell.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:05] "GET /pyr_4_sym.cell.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:05] "GET /MediumNet.net.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:06] "GET /AMPA_syn.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:06] "GET /AMPA_syn.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:06] "GET /AMPA_syn_inh.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:07] "GET /AMPA_syn_inh.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:07] "GET /bask.cell.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:07] "GET /bask.cell.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:07] "GET /Kdr_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:07] "GET /Kdr_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:07] "GET /LeakConductance_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:08] "GET /LeakConductance_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:08] "GET /Na_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:08] "GET /Na_bask.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:08] "GET /Ca_conc.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:09] "GET /Ca_conc.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:09] "GET /Ca_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:09] "GET /Ca_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:09] "GET /GABA_syn.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:10] "GET /GABA_syn.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:10] "GET /GABA_syn_inh.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:10] "GET /GABA_syn_inh.synapse.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:10] "GET /Kahp_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:11] "GET /Kahp_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:11] "GET /Kdr_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:11] "GET /Kdr_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:11] "GET /LeakConductance_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:12] "GET /LeakConductance_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:12] "GET /Na_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:12] "GET /Na_pyr.channel.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:12] "GET /pyr_4_sym.cell.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:13] "GET /pyr_4_sym.cell.nml HTTP/1.1" 200 -
127.0.0.1 - - [07/Feb/2015 22:27:46] "GET /script.js HTTP/1.1" 200 -

Do the multiple identical GET make sense? Are things parsed each time a GET is made?

@tarelli
Copy link
Member Author

tarelli commented Feb 8, 2015

The multiple GET I fixed already, I'm still debugging it, the comic strip in your desk describes well where I am, about to spot some bugs in the fabric of the universe itself.

@tarelli
Copy link
Member Author

tarelli commented Feb 8, 2015

The auditory cortex parsing time once I rewrote the inclusion reader, now the NeuroML file doesn't contain anymore NeuroML types (only its LEMS counterpart does). "NeuroML is LEMS" FTW.

[2015-02-08 21:01:45.936] INFO  http-bio-8080-exec-13        org.geppetto.model.neuroml.utils.OptimizedLEMSReader              Inclusion iteration completed, took 0ms 
[2015-02-08 21:01:45.936] INFO  http-bio-8080-exec-13        org.geppetto.model.neuroml.utils.OptimizedLEMSReader              Check inclusion https://raw.githubusercontent.com/openworm/org.geppetto.samples/master/NeuroML/ACnet2/Na_pyr.channel.nml 
[2015-02-08 21:01:45.936] INFO  http-bio-8080-exec-13        org.geppetto.model.neuroml.utils.OptimizedLEMSReader              Inclusion iteration completed, took 0ms 
[2015-02-08 21:01:45.938] INFO  http-bio-8080-exec-13        org.geppetto.model.neuroml.utils.OptimizedLEMSReader              Inclusion iteration completed, took 135ms 
[2015-02-08 21:01:45.949] INFO  http-bio-8080-exec-13        org.geppetto.model.neuroml.utils.OptimizedLEMSReader              Processed all inclusions, took 3576ms 
[2015-02-08 21:01:45.957] INFO  http-bio-8080-exec-13        o.geppetto.model.neuroml.services.NeuroMLModelInterpreterService  Parsed LEMS document, took 8ms 
[2015-02-08 21:01:46.184] INFO  http-bio-8080-exec-13        o.geppetto.model.neuroml.services.NeuroMLModelInterpreterService  Parsed NeuroML document of size 233KB, took 226ms 
[2015-02-08 21:01:46.185] INFO  http-bio-8080-exec-13        org.geppetto.simulation.visitor.LoadSimulationVisitor             Finished reading model, took 3813 ms  
[2015-02-08 21:01:46.185] INFO  http-bio-8080-exec-13        org.geppetto.simulation.visitor.LoadSimulationVisitor             Finished initializing simulator, took 0 ms  
[2015-02-08 21:01:46.204] INFO  http-bio-8080-exec-13        o.geppetto.model.neuroml.services.NeuroMLModelInterpreterService  Extracted connections, took 18ms 
[2015-02-08 21:01:46.204] INFO  http-bio-8080-exec-13        o.geppetto.model.neuroml.services.NeuroMLModelInterpreterService  Extracted subEntities, took 19ms 
[2015-02-08 21:01:46.209] INFO  http-bio-8080-exec-13        org.geppetto.simulator.jlems.NeuroMLSimulatorService              Populate visual tree completed, took 3ms 
[2015-02-08 21:01:46.298] INFO  http-bio-8080-exec-13        org.geppetto.frontend.MultiuserSimulationCallback                 Simulation Frontend Update Starting: 21:01:46:297 
[2015-02-08 21:01:46.548] INFO  http-bio-8080-exec-13        org.geppetto.frontend.controllers.GeppettoServletController       88ms were spent sending a message of 6913KB to the client 
[2015-02-08 21:01:46.548] INFO  http-bio-8080-exec-13        org.geppetto.frontend.MultiuserSimulationCallback                 Simulation Frontend Update Finished: Took:251 
[2015-02-08 21:01:46.548] INFO  http-bio-8080-exec-13        org.geppetto.simulation.SimulationService                         Simulation sent to callback listener 
[2015-02-08 21:01:46.548] INFO  http-bio-8080-exec-13        org.geppetto.simulation.SimulationService                         Total initialization time took 4476 ms

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tarelli tarelli

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@tarelli @borismarin