Skip calling debug statements with expensive json.dumps() (#238)

* Skip calling debug statements with expensive json.dumps() unless debugging is enabled.

* Add typeshed stubs for logging with isEnabledFor() bugfix.

Author: tetron

cwltool/draft2tool.py

@@ -259,11 +259,12 @@ def rm_pending_output_callback(output_callback, jobcachepending,
         j.hints = self.hints
         j.name = jobname
 
-        _logger.debug(u"[job %s] initializing from %s%s",
-                     j.name,
-                     self.tool.get("id", ""),
-                     u" as part of %s" % kwargs["part_of"] if "part_of" in kwargs else "")
-        _logger.debug(u"[job %s] %s", j.name, json.dumps(joborder, indent=4))
+        if _logger.isEnabledFor(logging.DEBUG):
+            _logger.debug(u"[job %s] initializing from %s%s",
+                         j.name,
+                         self.tool.get("id", ""),
+                         u" as part of %s" % kwargs["part_of"] if "part_of" in kwargs else "")
+            _logger.debug(u"[job %s] %s", j.name, json.dumps(joborder, indent=4))
 
 
         builder.pathmapper = None
@@ -274,7 +275,8 @@ def rm_pending_output_callback(output_callback, jobcachepending,
         builder.pathmapper = self.makePathMapper(reffiles, builder.stagedir, **make_path_mapper_kwargs)
         builder.requirements = j.requirements
 
-        _logger.debug(u"[job %s] path mappings is %s", j.name, json.dumps({p: builder.pathmapper.mapper(p) for p in builder.pathmapper.files()}, indent=4))
+        if _logger.isEnabledFor(logging.DEBUG):
+            _logger.debug(u"[job %s] path mappings is %s", j.name, json.dumps({p: builder.pathmapper.mapper(p) for p in builder.pathmapper.files()}, indent=4))
 
         _check_adjust = partial(check_adjust, builder)
 
@@ -297,7 +299,8 @@ def rm_pending_output_callback(output_callback, jobcachepending,
             if os.path.isabs(j.stdout) or ".." in j.stdout or not j.stdout:
                 raise validate.ValidationException("stdout must be a relative path")
 
-        _logger.debug(u"[job %s] command line bindings is %s", j.name, json.dumps(builder.bindings, indent=4))
+        if _logger.isEnabledFor(logging.DEBUG):
+            _logger.debug(u"[job %s] command line bindings is %s", j.name, json.dumps(builder.bindings, indent=4))
 
         dockerReq = self.get_requirement("DockerRequirement")[0]
         if dockerReq and kwargs.get("use_container"):
@@ -383,7 +386,8 @@ def collect_output_ports(self, ports, builder, outdir, compute_checksum=True):
             if fs_access.exists(custom_output):
                 with fs_access.open(custom_output, "r") as f:
                     ret = json.load(f)
-                _logger.debug(u"Raw output from %s: %s", custom_output, json.dumps(ret, indent=4))
+                if _logger.isEnabledFor(logging.DEBUG):
+                    _logger.debug(u"Raw output from %s: %s", custom_output, json.dumps(ret, indent=4))
             else:
                 for port in ports:
                     fragment = shortname(port["id"])

cwltool/job.py

@@ -315,7 +315,9 @@ def linkoutdir(src, tgt):
             _logger.warn(u"[job %s] completed %s", self.name, processStatus)
         else:
             _logger.debug(u"[job %s] completed %s", self.name, processStatus)
-        _logger.debug(u"[job %s] %s", self.name, json.dumps(outputs, indent=4))
+
+        if _logger.isEnabledFor(logging.DEBUG):
+            _logger.debug(u"[job %s] %s", self.name, json.dumps(outputs, indent=4))
 
         self.output_callback(outputs, processStatus)
 

cwltool/main.py

@@ -458,7 +458,8 @@ def load_job_order(args, t, stdin, print_input_deps=False, relative_deps=False,
 
             job_order_object.update({namemap[k]: v for k,v in cmd_line.items()})
 
-            _logger.debug(u"Parsed job order from command line: %s", json.dumps(job_order_object, indent=4))
+            if _logger.isEnabledFor(logging.DEBUG):
+                _logger.debug(u"Parsed job order from command line: %s", json.dumps(job_order_object, indent=4))
         else:
             job_order_object = None
 

cwltool/workflow.py

@@ -229,7 +229,8 @@ def receive_output(self, step, outputparms, jobout, processStatus):
                     _logger.error(u"Output is missing expected field %s" % i["id"])
                     processStatus = "permanentFail"
 
-        _logger.debug(u"[%s] produced output %s", step.name, json.dumps(jobout, indent=4))
+        if _logger.isEnabledFor(logging.DEBUG):
+            _logger.debug(u"[%s] produced output %s", step.name, json.dumps(jobout, indent=4))
 
         if processStatus != "success":
             if self.processStatus != "permanentFail":
@@ -312,9 +313,13 @@ def valueFromFunc(k, v):  # type: (Any, Any) -> Any
                                                          # https://github.com/python/mypy/issues/797
                                                                callback), 0, **kwargs))
             else:
-                _logger.debug(u"[job %s] job input %s", step.name, json.dumps(inputobj, indent=4))
+                if _logger.isEnabledFor(logging.DEBUG):
+                    _logger.debug(u"[job %s] job input %s", step.name, json.dumps(inputobj, indent=4))
+
                 inputobj = postScatterEval(inputobj)
-                _logger.debug(u"[job %s] evaluated job input to %s", step.name, json.dumps(inputobj, indent=4))
+
+                if _logger.isEnabledFor(logging.DEBUG):
+                    _logger.debug(u"[job %s] evaluated job input to %s", step.name, json.dumps(inputobj, indent=4))
                 jobs = step.job(inputobj, callback, **kwargs)
 
             step.submitted = True