search

drj826 / SML

This is the Perl 5 implementation of the SML code library. SML is a minimalistic plain text descriptive markup language which is human readable, enables continuous integration of documentation, expresses and validates semantic relationships, is easy to edit, is easy to generate automatically, and publishes professional documentation from plain text manuscripts.
GNU General Public License v3.0
2 stars 2 forks source link

3.5x Performance Degradation After Change Page Implementation #63

Closed drj826 closed 8 years ago

drj826 commented 8 years ago

Before implementing the library and document change pages it took about 4 minutes to publish the library and now it takes 14 minutes:

2016/01/10 17:05:46 INFO SML Engineering Library 
2016/01/10 17:05:46 INFO ------------------------------ ------ 
2016/01/10 17:05:46 INFO allocation count:                 326 
2016/01/10 17:05:46 INFO configuration_item count:          32 
2016/01/10 17:05:46 INFO requirement count:                356 
2016/01/10 17:05:46 INFO role count:                         3 
2016/01/10 17:05:46 INFO test count:                        34 
2016/01/10 17:05:46 INFO ------------------------------ ------ 
2016/01/10 17:05:46 INFO TOTAL ENTITY COUNT:               751 
2016/01/10 17:05:46 INFO  
2016/01/10 17:05:46 INFO ------------------------------ ------ 
2016/01/10 17:05:46 INFO ATTACHMENT count:                   1 
2016/01/10 17:05:46 INFO DEMO count:                         1 
2016/01/10 17:05:46 INFO DOCUMENT count:                     6 
2016/01/10 17:05:46 INFO EPIGRAPH count:                     4 
2016/01/10 17:05:46 INFO EXERCISE count:                     1 
2016/01/10 17:05:46 INFO FIGURE count:                      17 
2016/01/10 17:05:46 INFO KEYPOINTS count:                    1 
2016/01/10 17:05:46 INFO LISTING count:                     80 
2016/01/10 17:05:46 INFO PREFORMATTED count:                 1 
2016/01/10 17:05:46 INFO QUOTATION count:                    1 
2016/01/10 17:05:46 INFO RAW count:                         14 
2016/01/10 17:05:46 INFO SECTION count:                    129 
2016/01/10 17:05:46 INFO SLIDE count:                        1 
2016/01/10 17:05:46 INFO SOURCE count:                      19 
2016/01/10 17:05:46 INFO TABLE count:                       19 
2016/01/10 17:05:46 INFO VERSION_HISTORY count:              6 
2016/01/10 17:05:46 INFO ------------------------------ ------ 
2016/01/10 17:05:46 INFO TOTAL STRUCTURE COUNT:            301 
2016/01/10 17:05:46 INFO  
2016/01/10 17:05:46 INFO ------------------------------ ------ 
2016/01/10 17:05:46 INFO Division Declaration Rules:        44 
2016/01/10 17:05:46 INFO Property Declaration Rules:       643 
2016/01/10 17:05:46 INFO Composition Declaration Rules:    280 
2016/01/10 17:05:46 INFO Enumeration Declaration Rules:     32 
2016/01/10 17:05:46 INFO Default Declaration Rules:          2 
2016/01/10 17:05:46 INFO ------------------------------ ------ 
2016/01/10 17:05:46 INFO TOTAL ONTOLOGY RULE COUNT:       1001 
2016/01/10 17:05:46 INFO  
2016/01/10 17:05:46 INFO publish library 
2016/01/10 17:05:46 INFO get all library entities 
2016/01/10 17:06:02 INFO get all library entities 16 seconds 
2016/01/10 17:06:02 INFO get all library documents 
2016/01/10 17:07:00 INFO get all library documents 58 seconds 
2016/01/10 17:07:00 INFO update sha digest file 
2016/01/10 17:07:00 INFO update sha digest file 0 seconds 
2016/01/10 17:07:00 INFO publish default html sml-ug 
2016/01/10 17:09:33 INFO publish default html sml-ug 2 minutes and 33 seconds 
2016/01/10 17:09:33 INFO publish default html sml-brd 
2016/01/10 17:09:39 INFO publish default html sml-brd 6 seconds 
2016/01/10 17:09:39 INFO publish default html sml-dfrd 
2016/01/10 17:17:04 INFO publish default html sml-dfrd 7 minutes and 25 seconds 
2016/01/10 17:17:04 INFO publish default html sml-srd 
2016/01/10 17:18:37 INFO publish default html sml-srd 1 minute and 33 seconds 
2016/01/10 17:18:37 INFO publish default html sml-sdd 
2016/01/10 17:19:13 INFO publish default html sml-sdd 36 seconds 
2016/01/10 17:19:13 INFO publish default html sml-ted 
2016/01/10 17:19:31 INFO publish default html sml-ted 18 seconds 
2016/01/10 17:19:31 INFO publish default html library pages 
2016/01/10 17:19:54 INFO publish default html library pages 23 seconds 
2016/01/10 17:19:54 INFO publish default html library index 
2016/01/10 17:19:54 INFO publish default html library index 0 seconds 
2016/01/10 17:19:54 INFO publish library 14 minutes and 9 seconds

The parsing functions take the same amount of time. The publishing functions have slowed down significantly.

drj826 commented 8 years ago

Disabling publishing of the library and document change pages resulted in the execution time returning to a reasonable range (4 minutes 12 seconds):

INFO SML Engineering Library
INFO ------------------------------ ------
INFO allocation count:                 326
INFO configuration_item count:          32
INFO requirement count:                356
INFO role count:                         3
INFO test count:                        34
INFO ------------------------------ ------
INFO TOTAL ENTITY COUNT:               751
INFO
INFO ------------------------------ ------
INFO ATTACHMENT count:                   1
INFO DEMO count:                         1
INFO DOCUMENT count:                     6
INFO EPIGRAPH count:                     4
INFO EXERCISE count:                     1
INFO FIGURE count:                      17
INFO KEYPOINTS count:                    1
INFO LISTING count:                     80
INFO PREFORMATTED count:                 1
INFO QUOTATION count:                    1
INFO RAW count:                         14
INFO SECTION count:                    129
INFO SLIDE count:                        1
INFO SOURCE count:                      19
INFO TABLE count:                       19
INFO VERSION_HISTORY count:              6
INFO ------------------------------ ------
INFO TOTAL STRUCTURE COUNT:            301
INFO
INFO ------------------------------ ------
INFO Division Declaration Rules:        44
INFO Property Declaration Rules:       643
INFO Composition Declaration Rules:    280
INFO Enumeration Declaration Rules:     32
INFO Default Declaration Rules:          2
INFO ------------------------------ ------
INFO TOTAL ONTOLOGY RULE COUNT:       1001
INFO
INFO publish library
INFO get all library entities
INFO get all library entities 16 seconds
INFO get all library documents
INFO get all library documents 58 seconds
INFO update sha digest file
INFO update sha digest file 0 seconds
INFO publish default html sml-ug
INFO publish default html sml-ug 29 seconds
INFO publish default html sml-brd
INFO publish default html sml-brd 5 seconds
INFO publish default html sml-dfrd
INFO publish default html sml-dfrd 48 seconds
INFO publish default html sml-srd
INFO publish default html sml-srd 31 seconds
INFO publish default html sml-sdd
INFO publish default html sml-sdd 27 seconds
INFO publish default html sml-ted
INFO publish default html sml-ted 15 seconds
INFO publish default html library pages
INFO publish default html library pages 23 seconds
INFO publish default html library index
INFO publish default html library index 0 seconds
INFO publish library 4 minutes and 12 seconds

This gives me a theory of the problem. I believe my implementation of the change page publishing unnecessarily recomputes certain values over and over again. I'll re-write the implementation to ensure no computational work is repeated unnecessarily.

drj826 commented 8 years ago

After refactoring the code I'm happy with the performance. We're back down to 4 minutes 14 seconds to publish the library with library and document change pages:

INFO SML Engineering Library
INFO ------------------------------ ------
INFO allocation count:                 326
INFO configuration_item count:          32
INFO requirement count:                356
INFO role count:                         3
INFO test count:                        34
INFO ------------------------------ ------
INFO TOTAL ENTITY COUNT:               751
INFO
INFO ------------------------------ ------
INFO ATTACHMENT count:                   1
INFO DEMO count:                         1
INFO DOCUMENT count:                     6
INFO EPIGRAPH count:                     4
INFO EXERCISE count:                     1
INFO FIGURE count:                      17
INFO KEYPOINTS count:                    1
INFO LISTING count:                     80
INFO PREFORMATTED count:                 1
INFO QUOTATION count:                    1
INFO RAW count:                         14
INFO SECTION count:                    129
INFO SLIDE count:                        1
INFO SOURCE count:                      19
INFO TABLE count:                       19
INFO VERSION_HISTORY count:              6
INFO ------------------------------ ------
INFO TOTAL STRUCTURE COUNT:            301
INFO
INFO ------------------------------ ------
INFO Division Declaration Rules:        44
INFO Property Declaration Rules:       643
INFO Composition Declaration Rules:    280
INFO Enumeration Declaration Rules:     32
INFO Default Declaration Rules:          2
INFO ------------------------------ ------
INFO TOTAL ONTOLOGY RULE COUNT:       1001
INFO
INFO publish library
INFO get all library entities
INFO get all library entities 16 seconds
INFO get all library documents
INFO get all library documents 58 seconds
INFO update sha digest file
INFO update sha digest file 0 seconds
INFO publish default html sml-ug
INFO publish default html sml-ug 29 seconds
INFO publish default html sml-brd
INFO publish default html sml-brd 5 seconds
INFO publish default html sml-dfrd
INFO publish default html sml-dfrd 50 seconds
INFO publish default html sml-srd
INFO publish default html sml-srd 30 seconds
INFO publish default html sml-sdd
INFO publish default html sml-sdd 29 seconds
INFO publish default html sml-ted
INFO publish default html sml-ted 15 seconds
INFO publish default html library pages
INFO publish default html library pages 22 seconds
INFO publish default html library index
INFO publish default html library index 0 seconds
INFO publish library 4 minutes and 14 seconds