search

NeuroML / org.neuroml.model

NeuroML v2 Java API
https://www.neuroml.org/neuromlv2
GNU Lesser General Public License v3.0
5 stars 3 forks source link

Parsing performance #10

Open tarelli opened 9 years ago

tarelli commented 9 years ago

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 commented 9 years ago

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

borismarin commented 9 years ago

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 commented 9 years ago

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 commented 9 years ago

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