Announcement Announcement Module
Collapse
No announcement yet.
What does loading process do? It takes more than 20 hours in my case. Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • What does loading process do? It takes more than 20 hours in my case.

    I use Spring Batch with deicision tags (and many next tags).
    And loading time of the applicationContext.xml is over 20 hours.
    So I want to know "what dose the loading process do?".
    And I also want to know "why is the loading time so long?".


    enviroment:
    Spring 2.5.6
    Spring Batch 2.1.2
    java 1.6


    sample xml is below:
    Code:
    <job id="jobFile" xmlns="http://www.springframework.org/schema/batch" incrementer="jobParametersIncrementer" >
         <decision decider="bean.Decider1" id="step1">
            <next on="c1" to="step2"/>
            <next on="c2" to="step3"/>
            ....
         </decision>
         
         <decision decider="bean.Decider2" id="step2">
            <next on="cc1" to="step4"/>
            <next on="cc2" to="step5"/>
            ....
         </decision>
         
         <step id="step3" next="step4">
         </step>
         
         <step id="step4" next="step5">
         </step>
         
         <step id="step5" next="....">
           <flow id="flow1" />
        </step>
    </job>
    
    <flow id="flow1">
        <step id="flow1.step1" next="flow1.step2"/>
        <step id="flow1.step2" />
    </flow>
    Actually there are about 20 next tags in each decision tag.
    And if number of next tag is increasing , loading time will be more longer.
    (also number of next tag is increasing , flow tags is increasing too. So I don't know which tag is relating to loading time.)


    log sample is below:
    2011/03/29 17:36:43.531 DEBUG :: Returning cached instance of singleton bean 'bean.Decider1'
    2011/03/29 17:36:43.531 DEBUG :: Finished creating instance of bean '(inner bean)#12415'
    2011/03/29 17:36:43.531 DEBUG :: Finished creating instance of bean '(inner bean)#12415'
    2011/03/29 17:36:43.546 DEBUG :: Creating instance of bean '(inner bean)#12416'
    2011/03/29 17:36:43.546 DEBUG :: Creating instance of bean '(inner bean)#12416'
    2011/03/29 17:36:43.546 DEBUG :: Returning cached instance of singleton bean 'bean.Decider1'
    2011/03/29 17:36:43.546 DEBUG :: Finished creating instance of bean '(inner bean)#12416'
    2011/03/29 17:36:43.546 DEBUG :: Finished creating instance of bean '(inner bean)#12416'
    2011/03/29 17:36:43.562 DEBUG :: Creating instance of bean '(inner bean)#12417'
    2011/03/29 17:36:43.562 DEBUG :: Creating instance of bean '(inner bean)#12417'
    2011/03/29 17:36:43.562 DEBUG :: Returning cached instance of singleton bean 'bean.Decider1'
    2011/03/29 17:36:43.562 DEBUG :: Finished creating instance of bean '(inner bean)#12417'
    2011/03/29 17:36:43.562 DEBUG :: Finished creating instance of bean '(inner bean)#12417'
    2011/03/29 17:36:43.578 DEBUG :: Creating instance of bean '(inner bean)#12418'
    2011/03/29 17:36:43.593 DEBUG :: Creating instance of bean '(inner bean)#12418'
    2011/03/29 17:36:43.593 DEBUG :: Returning cached instance of singleton bean 'bean.Decider1'
    2011/03/29 17:36:43.593 DEBUG :: Finished creating instance of bean '(inner bean)#12418'
    2011/03/29 17:36:43.593 DEBUG :: Finished creating instance of bean '(inner bean)#12418'
    2011/03/29 17:36:43.593 DEBUG :: Creating instance of bean '(inner bean)#12419'
    2011/03/29 17:36:43.609 DEBUG :: Creating instance of bean '(inner bean)#12419'
    2011/03/29 17:36:43.609 DEBUG :: Returning cached instance of singleton bean 'bean.Decider1'
    2011/03/29 17:36:43.609 DEBUG :: Finished creating instance of bean '(inner bean)#12419'
    2011/03/29 17:36:43.609 DEBUG :: Finished creating instance of bean '(inner bean)#12419'
    2011/03/29 17:36:43.609 DEBUG :: Creating instance of bean '(inner bean)#12420'
    2011/03/29 17:36:43.625 DEBUG :: Creating instance of bean '(inner bean)#12420'
    2011/03/29 17:36:43.625 DEBUG :: Returning cached instance of singleton bean 'bean.Decider1'
    2011/03/29 17:36:43.625 DEBUG :: Finished creating instance of bean '(inner bean)#12420'
    2011/03/29 17:36:43.625 DEBUG :: Finished creating instance of bean '(inner bean)#12420'
    2011/03/29 17:36:43.640 DEBUG :: Creating instance of bean '(inner bean)#12421'
    2011/03/29 17:36:43.640 DEBUG :: Creating instance of bean '(inner bean)#12421'

    The output is continuing more than 8000 lines.
    And then log outputs "Job execution starting:".

    Please help me, if you have the information about this.


    Thank you very much for reading my strange english.
    Last edited by hirom; Aug 4th, 2011, 09:02 AM.

  • #2
    Please use [ code][/code ] tags when posting code, that way it remains readable.

    For starters I suggest disabling debug logging, logging/writing to a console is slow so that has quite an impact on performance. Also if there are a lot of beans all of them need to be processed (but 20 hours! is quite long).

    Comment


    • #3
      perhaps some <import /> loop? looks like the same bean is created again and again. Check if some XML files don't import themselves recursively.

      Comment


      • #4
        Originally posted by Marten Deinum View Post
        Please use [ code][/code ] tags when posting code, that way it remains readable.

        For starters I suggest disabling debug logging, logging/writing to a console is slow so that has quite an impact on performance. Also if there are a lot of beans all of them need to be processed (but 20 hours! is quite long).
        I'm sorry about code tags.
        I improved above code.

        Maybe it doesn't matter about debug logging.
        I used Spring Batch without debug logging, and it took more than 20 hours.
        So I changed to debug logging mode.

        But thank you for your suggestion. I'm glad.

        Comment


        • #5
          Originally posted by arno View Post
          perhaps some <import /> loop? looks like the same bean is created again and again. Check if some XML files don't import themselves recursively.
          Thank you for your replying.
          It seems to be surely possible, I think.
          I will investigate about your suggestion.
          And I will report the result.

          Comment


          • #6
            Now I make recursive import file, and run Spring Batch.
            Then it turned out that spring throws exception, if it detects recursive import definitions.

            result log is below:
            Code:
            Caused by: org.springframework.beans.factory.BeanDefinitionStoreException: 
            Detected recursive loading of class path resource [sample/run-testManyDecider.xml] - check your import definitions!
            So the cause of long time loading is not <import /> loop.
            Because no exception occur at above first sample.
            Last edited by hirom; Mar 31st, 2011, 10:34 AM.

            Comment


            • #7
              Each of those "inner bean" logs is showing the creation of a DecisionState in the JobFlow. If you have >12000 such inner beans that is a *huge* flow, but even so they are only taking 10-15ms each to create, so I don't see where it adds up to 20 hours. You must have on order 5 million(!) states in your flow to take that long.

              Spring Batch isn't doing anything very unusual - just creating bean definitions. Nobody has a Spring application context with 5 million beans, honestly, so you must be doing something odd.

              A quick test on my PC has a DecisionState being created in more like 1-2ms so maybe your computer is feeble, or under load from something else?

              I think you should explain why you need such a huge flow (probably it's the wrong tool for your job), and also look at other Spring contexts to see if they load abnormally slowly as well.

              Comment


              • #8
                Is it possible for you to zip your project (some code and configuration) and attach it here? It makes it easier to troubleshoot... There must be something wrong or odd with your configuration (you aren't creating/loading new instances of a context yourself are you?!)

                Comment


                • #9
                  Originally posted by Dave Syer View Post
                  Each of those "inner bean" logs is showing the creation of a DecisionState in the JobFlow. If you have >12000 such inner beans that is a *huge* flow, but even so they are only taking 10-15ms each to create, so I don't see where it adds up to 20 hours. You must have on order 5 million(!) states in your flow to take that long.

                  Spring Batch isn't doing anything very unusual - just creating bean definitions. Nobody has a Spring application context with 5 million beans, honestly, so you must be doing something odd.


                  Thank you for replynig.
                  I will show number of tags on my configuration.

                  number of tags is below:
                  bean tags ...538
                  step tags ...162
                  next tags ...92
                  decision tags ...15
                  flow tags ...146

                  I thought number of tags above is not so strange, but actually there are a lot of inner beans.
                  Now I suspect my miss on configuration again.
                  And I will investigate my configuration again.
                  If I find new facts, I will post the information on this thread or new thread.

                  Thanks.

                  Comment


                  • #10
                    Originally posted by Marten Deinum View Post
                    Is it possible for you to zip your project (some code and configuration) and attach it here?
                    Thank you for your advice.
                    But it is difficult to post zip, because there are some information which is unable to show someone.
                    I am so sorry.

                    I will investigate my configuration again.
                    And if there are available informations for someone who encountered the same trouble, I will report it on this thread.

                    Thanks.

                    Comment


                    • #11
                      I investigated my configuration again.
                      And I can't get any answers.
                      But I resolved this problem, so I write how to resolve this.

                      I rewrote flow tags to job tags.
                      Sample is below:
                      before:
                      Code:
                      <job id="jobFile"  ... >
                          ....   
                          <step id="step5" next="....">
                            <flow id="flow1" />
                          </step>
                        </job>
                      
                        <flow id="flow1">
                          <step id="flow1.step1" next="flow1.step2"/>
                          <step id="flow1.step2"/>
                        </flow>
                      after:
                      Code:
                        <job id="jobFile"  ... >
                          ....   
                          <step id="step5" next="....">
                            <job ref="job1.flow1" job-launcher="jobLauncher" 
                                job-parameters-extractor="jobParametersExtractor"/>
                          </step>
                        </job>
                      
                        <job id="job1.flow1" restartable="true">
                          <step id="flow1.step1" next="flow1.step2"/>
                          <step id="flow1.step2" />
                        </job>
                      I don't know the reason, but above modification makes SpringBatch work well.
                      The loading time become about 10sec!

                      Thank you for many comments!
                      Last edited by hirom; Aug 4th, 2011, 09:03 AM.

                      Comment


                      • #12
                        That's slightly worrying, if still puzzling (because no-one else has the problem), but it's good that you have a workaround. I raised a JIRA ticket for you (https://jira.springsource.org/browse/BATCH-1782).

                        Comment

                        Working...
                        X