resolves #2574 record timings when calling convert and write on Document

- store timings object on Document
- record timing for convert in Document#convert
- record timing for write in Document#write

3 files changed, 26 insertions, 7 deletions

diff --git a/lib/asciidoctor.rb b/lib/asciidoctor.rb
index 9897ada8..a36a55f9 100644
--- a/lib/asciidoctor.rb
+++ b/lib/asciidoctor.rb
@@ -1287,6 +1287,7 @@ module Asciidoctor
   # Returns the Document
   def load input, options = {}
     options = options.dup
+
     if (timings = options[:timings])
       timings.start :read
     end
@@ -1511,15 +1512,11 @@ module Asciidoctor
       outdir = nil
     end
 
-    timings.start :convert if timings
     opts = outfile && !stream_output ? { 'outfile' => outfile, 'outdir' => outdir } : {}
     output = doc.convert opts
-    timings.record :convert if timings
 
     if outfile
-      timings.start :write if timings
       doc.write output, outfile
-      timings.record :write if timings
 
       # NOTE document cannot control this behavior if safe >= SafeMode::SERVER
       # NOTE skip if stylesdir is a URI
diff --git a/lib/asciidoctor/document.rb b/lib/asciidoctor/document.rb
index 4863bfc3..3e0ff016 100644
--- a/lib/asciidoctor/document.rb
+++ b/lib/asciidoctor/document.rb
@@ -259,6 +259,7 @@ class Document < AbstractBlock
       @safe = parent_doc.safe
       @attributes['compat-mode'] = '' if (@compat_mode = parent_doc.compat_mode)
       @sourcemap = parent_doc.sourcemap
+      @timings = nil
       @converter = parent_doc.converter
       initialize_extensions = false
       @extensions = parent_doc.extensions
@@ -309,6 +310,7 @@ class Document < AbstractBlock
       end
       @compat_mode = attr_overrides.key? 'compat-mode'
       @sourcemap = options[:sourcemap]
+      @timings = options.delete :timings
       @converter = nil
       initialize_extensions = defined? ::Asciidoctor::Extensions
       @extensions = nil # initialize furthur down
@@ -1100,9 +1102,8 @@ class Document < AbstractBlock
   # loaded by the Converter. If a :template_dir is not specified,
   # or a template is missing, the converter will fall back to
   # using the appropriate built-in template.
-  #--
-  # QUESTION should we dup @header_attributes before converting?
   def convert opts = {}
+    @timings.start :convert if @timings
     parse unless @parsed
     unless @safe >= SafeMode::SERVER || opts.empty?
       # QUESTION should we store these on the Document object?
@@ -1133,6 +1134,7 @@ class Document < AbstractBlock
       end
     end
 
+    @timings.record :convert if @timings
     output
   end
 
@@ -1143,7 +1145,10 @@ class Document < AbstractBlock
   #
   # If the converter responds to :write, delegate the work of writing the file
   # to that method. Otherwise, write the output the specified file.
+  #
+  # Returns nothing
   def write output, target
+    @timings.start :write if @timings
     if Writer === @converter
       @converter.write output, target
     else
@@ -1159,8 +1164,9 @@ class Document < AbstractBlock
       if @backend == 'manpage' && ::String === target && (@converter.respond_to? :write_alternate_pages)
         @converter.write_alternate_pages @attributes['mannames'], @attributes['manvolnum'], target
       end
-      nil
     end
+    @timings.record :write if @timings
+    nil
   end
 
 =begin
diff --git a/test/api_test.rb b/test/api_test.rb
index 1c39f265..8d52a2db 100644
--- a/test/api_test.rb
+++ b/test/api_test.rb
@@ -454,6 +454,14 @@ term without description::
       assert_kind_of Asciidoctor::List, result[1]
       assert_kind_of Asciidoctor::ListItem, result[2]
     end
+
+    test 'timings are recorded for each step when load and convert are called separately' do
+      sample_input_path = fixture_path 'asciidoc_index.txt'
+      (Asciidoctor.load_file sample_input_path, :timings => (timings = Asciidoctor::Timings.new)).convert
+      refute_equal '0.00000', '%05.5f' % timings.read_parse.to_f
+      refute_equal '0.00000', '%05.5f' % timings.convert.to_f
+      refute_equal timings.read_parse, timings.total
+    end
   end
   
   context 'Convert' do
@@ -785,5 +793,13 @@ text
         FileUtils.rm(sample_output_path)
       end
     end
+
+    test 'timings are recorded for each step' do
+      sample_input_path = fixture_path 'asciidoc_index.txt'
+      Asciidoctor.convert_file sample_input_path, :timings => (timings = Asciidoctor::Timings.new), :to_file => false
+      refute_equal '0.00000', '%05.5f' % timings.read_parse.to_f
+      refute_equal '0.00000', '%05.5f' % timings.convert.to_f
+      refute_equal timings.read_parse, timings.total
+    end
   end
 end