Utilize Ruby Logger class to created timestamped output to find performance issues. (#668)

Author: james-ball-qualcomm

Rakefile

@@ -11,6 +11,7 @@ require "etc"
 $root = Pathname.new(__FILE__).dirname.realpath
 $lib = $root / "lib"
 
+require "logger"
 require "ruby-progressbar"
 require "yard"
 require "minitest/test_task"
@@ -19,6 +20,12 @@ require_relative $root / "lib" / "architecture"
 require_relative $root / "lib" / "portfolio_design"
 require_relative $root / "lib" / "proc_cert_design"
 
+$logger = Logger.new(STDOUT, datetime_format: "%v %r")
+$logger.level = Logger::INFO
+$logger.formatter = proc do |severity, datetime, progname, msg|
+  "[#{severity}] #{datetime.strftime('%F %T')}: #{msg}\n"
+end
+
 directory "#{$root}/.stamps"
 
 # Load and execute Rakefile for each backend.
@@ -426,22 +433,22 @@ namespace :test do
     These are basic but fast-running tests to check the database and tools
   DESC
   task :smoke do
-    puts "UPDATE: Starting test:smoke"
-    puts "UPDATE: Running gen:isa_explorer_browser_ext"
+    $logger.info "Starting test:smoke"
+    $logger.info "Running gen:isa_explorer_browser_ext"
     Rake::Task["gen:isa_explorer_browser_ext"].invoke
-    puts "UPDATE: Running test:idl_compiler"
+    $logger.info "Running test:idl_compiler"
     Rake::Task["test:idl_compiler"].invoke
-    puts "UPDATE: Running test:lib"
+    $logger.info "Running test:lib"
     Rake::Task["test:lib"].invoke
-    puts "UPDATE: Running test:schema"
+    $logger.info "Running test:schema"
     Rake::Task["test:schema"].invoke
-    puts "UPDATE: Running test:idl"
+    $logger.info "Running test:idl"
     Rake::Task["test:idl"].invoke
-    puts "UPDATE: Running test:inst_encodings"
+    $logger.info "Running test:inst_encodings"
     Rake::Task["test:inst_encodings"].invoke
-    puts "UPDATE: Running test:llvm"
+    $logger.info "Running test:llvm"
     Rake::Task["test:llvm"].invoke
-    puts "UPDATE: Done test:smoke"
+    $logger.info "Done test:smoke"
   end
 
   desc <<~DESC
@@ -450,41 +457,41 @@ namespace :test do
     These tests must pass before a commit will be allowed in the main branch on GitHub
   DESC
   task :regress do
-    puts "UPDATE: Starting test:regress"
+    $logger.info "Starting test:regress"
     Rake::Task["test:smoke"].invoke
 
-    puts "UPDATE: Running gen:isa_explorer_browser"
+    $logger.info "Running gen:isa_explorer_browser"
     Rake::Task["gen:isa_explorer_browser"].invoke
 
-    puts "UPDATE: Running gen:isa_explorer_spreadsheet"
+    $logger.info "Running gen:isa_explorer_spreadsheet"
     Rake::Task["gen:isa_explorer_spreadsheet"].invoke
 
-    puts "UPDATE: Running gen:html_manual MANUAL_NAME=isa VERSIONS=all"
+    $logger.info "Running gen:html_manual MANUAL_NAME=isa VERSIONS=all"
     ENV["MANUAL_NAME"] = "isa"
     ENV["VERSIONS"] = "all"
     Rake::Task["gen:html_manual"].invoke
 
-    puts "UPDATE: Running gen:ext_pdf EXT=B VERSION=latest"
+    $logger.info "Running gen:ext_pdf EXT=B VERSION=latest"
     ENV["EXT"] = "B"
     ENV["VERSION"] = "latest"
     Rake::Task["gen:ext_pdf"].invoke
 
-    puts "UPDATE: Running gen:html for example_rv64_with_overlay"
+    $logger.info "Running gen:html for example_rv64_with_overlay"
     Rake::Task["gen:html"].invoke("example_rv64_with_overlay")
 
-    puts "UPDATE: Generating MockProcessor-CRD.pdf"
+    $logger.info "Generating MockProcessor-CRD.pdf"
     Rake::Task["#{$root}/gen/proc_crd/pdf/MockProcessor-CRD.pdf"].invoke
 
-    puts "UPDATE: Generating MockProcessor-CTP.pdf"
+    $logger.info "Generating MockProcessor-CTP.pdf"
     Rake::Task["#{$root}/gen/proc_ctp/pdf/MockProcessor-CTP.pdf"].invoke
 
-    puts "UPDATE: Generating MockProfileRelease.pdf"
+    $logger.info "Generating MockProfileRelease.pdf"
     Rake::Task["#{$root}/gen/profile/pdf/MockProfileRelease.pdf"].invoke
 
-    puts "UPDATE: Generating Go Language Support"
+    $logger.info "Generating Go Language Support"
     Rake::Task["gen:go"].invoke
 
-    puts "UPDATE: Done test:regress"
+    $logger.info "Done test:regress"
   end
 
   desc <<~DESC

backends/cfg_html_doc/html_gen.rake

@@ -230,6 +230,8 @@ rule %r{#{$root}/\.stamps/html-gen-.*\.stamp} => proc { |tname|
   playbook_path = $root / "gen" / "cfg_html_doc" / config_name / "antora" / "playbook.yaml"
   Rake::Task[playbook_path].invoke
 
+  $logger.info "Running Antora under npm to create #{config_name}"
+
   sh [
     "npm exec -- antora",
     "--stacktrace",
@@ -240,6 +242,9 @@ rule %r{#{$root}/\.stamps/html-gen-.*\.stamp} => proc { |tname|
     "--fetch",
     playbook_path
   ].join(" ")
+
+  $logger.info "Done running Antora under npm to create #{config_name}"
+
   FileUtils.touch t.name
 end
 

backends/isa_explorer/isa_explorer.rb

@@ -237,40 +237,40 @@ def gen_xlsx(arch, output_pname)
   raise ArgumentError, "output_pname is a #{output_pname.class} class but needs to be String" unless output_pname.is_a?(String)
 
   # Create a new Excel workbook
-  puts "UPDATE: Creating Excel workboook #{output_pname}"
+  $logger.info "Creating Excel workboook #{output_pname}"
   workbook = WriteXLSX.new(output_pname)
 
   # Convert arch to ext_table data structure
-  puts "UPDATE: Creating extension table data structure"
+  $logger.info "Creating extension table data structure"
   ext_table = arch2ext_table(arch)
 
   # Add a worksheet
   ext_worksheet = workbook.add_worksheet("Extensions")
 
   # Populate worksheet with ext_table
-  puts "UPDATE: Adding extension table to worksheet #{ext_worksheet.name}"
+  $logger.info "Adding extension table to worksheet #{ext_worksheet.name}"
   gen_xlsx_table(ext_table, workbook, ext_worksheet)
 
   # Convert arch to inst_table data structure
-  puts "UPDATE: Creating instruction table data structure"
+  $logger.info "Creating instruction table data structure"
   inst_table = arch2inst_table(arch)
 
   # Add a worksheet
   inst_worksheet = workbook.add_worksheet("Instructions")
 
   # Populate worksheet with inst_table
-  puts "UPDATE: Adding instruction table to worksheet #{inst_worksheet.name}"
+  $logger.info "Adding instruction table to worksheet #{inst_worksheet.name}"
   gen_xlsx_table(inst_table, workbook, inst_worksheet)
 
   # Convert arch to csr_table data structure
-  puts "UPDATE: Creating CSR table data structure"
+  $logger.info "Creating CSR table data structure"
   csr_table = arch2csr_table(arch)
 
   # Add a worksheet
   csr_worksheet = workbook.add_worksheet("CSRs")
 
   # Populate worksheet with csr
-  puts "UPDATE: Adding CSR table to worksheet #{csr_worksheet.name}"
+  $logger.info "Adding CSR table to worksheet #{csr_worksheet.name}"
   gen_xlsx_table(csr_table, workbook, csr_worksheet)
 
   workbook.close
@@ -359,10 +359,10 @@ def gen_js_ext_table(arch, output_pname)
   raise ArgumentError, "output_pname is a #{output_pname.class} class but needs to be String" unless output_pname.is_a?(String)
 
   # Convert arch to ext_table data structure
-  puts "UPDATE: Creating extension table data structure"
+  $logger.info "Creating extension table data structure"
   ext_table = arch2ext_table(arch)
 
-  puts "UPDATE: Converting extension table to #{output_pname}"
+  $logger.info "Converting extension table to #{output_pname}"
   gen_js_table(ext_table, "ext_table", output_pname)
 end
 
@@ -375,10 +375,10 @@ def gen_js_inst_table(arch, output_pname)
   raise ArgumentError, "output_pname is a #{output_pname.class} class but needs to be String" unless output_pname.is_a?(String)
 
   # Convert arch to inst_table data structure
-  puts "UPDATE: Creating instruction table data structure"
+  $logger.info "Creating instruction table data structure"
   inst_table = arch2inst_table(arch)
 
-  puts "UPDATE: Converting instruction table to #{output_pname}"
+  $logger.info "Converting instruction table to #{output_pname}"
   gen_js_table(inst_table, "inst_table", output_pname)
 end
 
@@ -391,10 +391,10 @@ def gen_js_csr_table(arch, output_pname)
   raise ArgumentError, "output_pname is a #{output_pname.class} class but needs to be String" unless output_pname.is_a?(String)
 
   # Convert arch to csr_table data structure
-  puts "UPDATE: Creating CSR table data structure"
+  $logger.info "Creating CSR table data structure"
   csr_table = arch2csr_table(arch)
 
-  puts "UPDATE: Converting CSR table to #{output_pname}"
+  $logger.info "Converting CSR table to #{output_pname}"
   gen_js_table(csr_table, "csr_table", output_pname)
 end
 

backends/manual/tasks.rake

@@ -410,17 +410,17 @@ namespace :gen do
       Rake::Task[antora_path / "antora.yml"].invoke
       Rake::Task[antora_path / "nav.adoc"].invoke
 
-      puts "UPDATE: Generating CSRs"
+      $logger.info "Generating CSRs"
       version_obj.csrs.each do |csr|
         Rake::Task[antora_path / "modules" / "csrs" / "pages" / "#{csr.name}.adoc"].invoke
       end
 
-      puts "UPDATE: Generating Instructions"
+      $logger.info "Generating Instructions"
       version_obj.instructions.each do |inst|
         Rake::Task[antora_path / "modules" / "insts" / "pages" / "#{inst.name}.adoc"].invoke
       end
 
-      puts "UPDATE: Generating Extensions"
+      $logger.info "Generating Extensions"
       version_obj.extensions.each do |ext|
         Rake::Task[antora_path / "modules" / "exts" / "pages" / "#{ext.name}.adoc"].invoke
       end
@@ -436,7 +436,7 @@ namespace :gen do
     playbook_path = MANUAL_GEN_DIR / ENV["MANUAL_NAME"] / "top" / output_hash / "antora" / "playbook" / "playbook.yml"
     Rake::Task[playbook_path].invoke
 
-    puts "UPDATE: Using npm to execute Antora"
+    $logger.info "Running Antora under npm for HTML site to create '#{MANUAL_GEN_DIR / ENV['MANUAL_NAME'] / output_hash / 'html'}'"
 
     sh [
       "npm exec -- antora",
@@ -449,7 +449,7 @@ namespace :gen do
       playbook_path.to_s
     ].join(" ")
 
-    puts "SUCCESS: HTML site written to '#{MANUAL_GEN_DIR / ENV['MANUAL_NAME'] / output_hash / 'html'}'"
+    $logger.info "Done running Antora under npm for HTML site to create '#{MANUAL_GEN_DIR / ENV['MANUAL_NAME'] / output_hash / 'html'}'"
   end
 end
 

backends/portfolio/tasks.rake

@@ -29,7 +29,7 @@ def pf_create_cfg_arch(portfolio_grp_with_arch)
   # otherwise there would be a circular dependency. To avoid this circular dependency, none of the routines
   # called in the PortfolioGroup object to satisfy the requests from the AbstractConfig API for the ConfiguredArchitecture
   # object can require that the PortfolioGroup DatabaseObjects contain a ConfiguredArchitecture.
-  cfg_arch_with_portfolio_grp_with_arch = ConfiguredArchitecture.new(
+  ConfiguredArchitecture.new(
     portfolio_grp_with_arch.name,
     PortfolioGroupConfig.new(portfolio_grp_with_arch),
     $root / "gen" / "resolved_arch" / "_"
@@ -68,6 +68,7 @@ end
 # @param target_pname [String] Full pathname of adoc file being generated
 # @param portfolio_design [PortfolioDesign] PortfolioDesign being generated
 def pf_create_adoc(erb_template_pname, erb_binding, target_pname, portfolio_design)
+  $logger.info "Reading ERB adoc template for #{portfolio_design.name}"
   template_path = Pathname.new(erb_template_pname)
   erb = ERB.new(File.read(template_path), trim_mode: "-")
   erb.filename = template_path.to_s
@@ -77,21 +78,22 @@ def pf_create_adoc(erb_template_pname, erb_binding, target_pname, portfolio_desi
 
   # Convert ERB to final ASCIIDOC. Note that this code is broken up into separate function calls
   # each with a variable name to aid in running a command-line debugger on this code.
-  puts "UPDATE: Converting ERB template to adoc for #{portfolio_design.name}"
+  $logger.info "Starting ERB adoc template evaluation for #{portfolio_design.name}"
   erb_result = erb.result(erb_binding)
+  $logger.info "Converting monospace formatting to internal link format"
   erb_result_monospace_converted_to_links = portfolio_design.convert_monospace_to_links(erb_result)
+  $logger.info "Converting internal link format to adoc links"
   erb_result_with_links_resolved = AsciidocUtils.resolve_links(erb_result_monospace_converted_to_links)
-
+  $logger.info "Writing adoc to #{target_pname}"
   File.write(target_pname, erb_result_with_links_resolved)
-  puts "UPDATE: Generated adoc in #{target_pname}"
 end
 
 # @param adoc_file [String] Full name of source adoc file
 # @param target_pname [String] Full name of PDF file being generated
 def pf_adoc2pdf(adoc_file, target_pname)
   FileUtils.mkdir_p File.dirname(target_pname)
 
-  puts "UPDATE: Generating PDF in #{target_pname}"
+  $logger.info "Generating PDF in #{target_pname}"
   cmd = [
     "asciidoctor-pdf",
     "-w",
@@ -107,7 +109,7 @@ def pf_adoc2pdf(adoc_file, target_pname)
     adoc_file
   ].join(" ")
 
-  puts "UPDATE: bundle exec #{cmd}"
+  $logger.info "bundle exec #{cmd}"
 
   # Write out command used to convert adoc to PDF to allow running this
   # manually during development.
@@ -121,15 +123,15 @@ def pf_adoc2pdf(adoc_file, target_pname)
   # Now run the actual command.
   sh cmd
 
-  puts "UPDATE: Generated PDF in #{target_pname}"
+  $logger.info "Generated PDF in #{target_pname}"
 end
 
 # @param adoc_file [String] Full name of source adoc file
 # @param target_pname [String] Full name of HTML file being generated
 def pf_adoc2html(adoc_file, target_pname)
   FileUtils.mkdir_p File.dirname(target_pname)
 
-  puts "UPDATE: Generating HTML in #{target_pname}"
+  $logger.info "Generating HTML in #{target_pname}"
   cmd = [
     "asciidoctor",
     "-w",
@@ -142,7 +144,7 @@ def pf_adoc2html(adoc_file, target_pname)
     adoc_file
   ].join(" ")
 
-  puts "UPDATE: bundle exec #{cmd}"
+  $logger.info "bundle exec #{cmd}"
 
    # Write out command used to convert adoc to HTML to allow running this
   # manually during development.
@@ -156,5 +158,5 @@ def pf_adoc2html(adoc_file, target_pname)
   # Now run the actual command.
   sh cmd
 
-  puts "UPDATE: Generated HTML in #{target_pname}"
+  $logger.info "Generated HTML in #{target_pname}"
 end

backends/proc_cert/tasks.rake

@@ -11,23 +11,24 @@ require "asciidoctor-diagram"
 # @param model_name [String] Name of the processor certificate model
 def proc_cert_create_adoc(erb_template_pname, target_pname, model_name)
   # Create Architecture object without any knowledge of certificate model.
+  $logger.info "Creating Architecture object for #{model_name}"
   arch = pf_create_arch
 
   # Create ProcCertModel for specific processor certificate model as specified in its arch YAML file.
   # The Architecture object also creates all other portfolio-related class instances from their arch YAML files.
   # None of these objects are provided with a AbstractConfig or Design object when created.
-  puts "UPDATE: Creating ProcCertModel with only an Architecture object for #{model_name}"
+  $logger.info "Creating ProcCertModel with only an Architecture object for #{model_name}"
   proc_cert_model_with_arch = arch.proc_cert_model(model_name)
 
   # Create the ConfiguredArchitecture object with knowledge of the ProcCertModel.
   # Needs a PortfolioGroup object so just create one with just one ProcCertModel (which is a child of Portfolio).
   cfg_arch = pf_create_cfg_arch(PortfolioGroup.new(model_name, [proc_cert_model_with_arch]))
 
-  puts "UPDATE: Creating ProcCertModel with a ConfiguredArchitecture object for #{model_name}"
+  $logger.info "Creating ProcCertModel with a ConfiguredArchitecture object for #{model_name}"
   proc_cert_model_with_cfg_arch = cfg_arch.proc_cert_model(model_name)
 
   # Create the one ProcCertDesign object required for the ERB evaluation using the cfg_arch.
-  puts "UPDATE: Creating ProcCertDesign object using processor certificate model #{model_name}"
+  $logger.info "Creating ProcCertDesign object using processor certificate model #{model_name}"
   proc_cert_design = ProcCertDesign.new(model_name, cfg_arch, ProcCertDesign.proc_ctp_type, proc_cert_model_with_cfg_arch,
     proc_cert_model_with_cfg_arch.proc_cert_class)
 

backends/proc_ctp/templates/proc_ctp.adoc.erb

@@ -177,13 +177,13 @@ This document is generated by a database backend so all views of the information
 <%= portfolio_design.include_erb("idl_func_appendix.adoc.erb") %>
 
 <<<
-<% puts "UPDATE: Including riscv-unprivileged.adoc" -%>
+<% $logger.info "Including riscv-unprivileged.adoc" -%>
 // Reset chapter numbering
 :!chapter-number:
 include::ext/riscv-isa-manual/src/riscv-unprivileged.adoc[]
 
 <<<
-<% puts "UPDATE: Including riscv-privileged.adoc" -%>
+<% $logger.info "Including riscv-privileged.adoc" -%>
 // Reset chapter numbering
 :!chapter-number:
 include::ext/riscv-isa-manual/src/riscv-privileged.adoc[]