diff --git a/actions/ost-compare-ligand-structures b/actions/ost-compare-ligand-structures index 07a687467f4aaf74b17f298db09bbd3476fe8cd6..12b3d7bfc27f4f9dd2af49c1f30507a29206b989 100644 --- a/actions/ost-compare-ligand-structures +++ b/actions/ost-compare-ligand-structures @@ -320,8 +320,6 @@ def _LoadStructure(structure_path, sformat, fault_tolerant, bu_id): The returned structure has structure_path attached as structure name """ - # increase loglevel, as we would pollute the info log with weird stuff - ost.PushVerbosityLevel(ost.LogLevel.Error) # Load the structure if sformat == "mmcif": if bu_id is not None: @@ -346,7 +344,6 @@ def _LoadStructure(structure_path, sformat, fault_tolerant, bu_id): raise Exception(f"No residues found in file: {structure_path}") # restore old loglevel and return - ost.PopVerbosityLevel() entity.SetName(structure_path) return entity @@ -528,6 +525,7 @@ def _Process(model, model_ligands, reference, reference_ligands, args): ################## if args.lddt_pli: + LogScript("Computing lDDT-PLI scores") out["lddt_pli"] = dict() out["lddt_pli"]["assigned_scores"] = list() for lig_pair in lddtpli_scorer.assignment: @@ -590,6 +588,7 @@ def _Process(model, model_ligands, reference, reference_ligands, args): if args.rmsd: + LogScript("Computing BiSyRMSD scores") out["rmsd"] = dict() out["rmsd"]["assigned_scores"] = list() for lig_pair in scrmsd_scorer.assignment: @@ -680,12 +679,15 @@ def _Main(): _CheckCompoundLib() try: # Load structures + LogScript("Loading data") + LogInfo("Loading reference structure") reference_format = _GetStructureFormat(args.reference, sformat=args.reference_format) reference = _LoadStructure(args.reference, sformat=reference_format, bu_id=args.reference_biounit, fault_tolerant = args.fault_tolerant) + LogInfo("Loading model structure") model_format = _GetStructureFormat(args.model, sformat=args.model_format) model = _LoadStructure(args.model, @@ -694,13 +696,19 @@ def _Main(): fault_tolerant = args.fault_tolerant) # Load ligands - model_ligands = _LoadLigands(args.model_ligands) + LogInfo("Loading reference ligands") reference_ligands = _LoadLigands(args.reference_ligands) + LogInfo("Loading model ligands") + model_ligands = _LoadLigands(args.model_ligands) # Cleanup + LogVerbose("Cleaning up reference structure") cleaned_reference = _CleanupStructure(reference) + LogVerbose("Cleaning up model structure") cleaned_model = _CleanupStructure(model) + LogVerbose("Cleaning up reference ligands") cleaned_reference_ligands = _CleanupLigands(reference_ligands) + LogVerbose("Cleaning up model ligands") cleaned_model_ligands = _CleanupLigands(model_ligands) # Validate diff --git a/modules/mol/alg/pymod/chain_mapping.py b/modules/mol/alg/pymod/chain_mapping.py index b19107ba5fc0640ed6a068a27517b0acd257a0aa..9d025f3161fa5b1f1fa586935eb6cfde1f6286fe 100644 --- a/modules/mol/alg/pymod/chain_mapping.py +++ b/modules/mol/alg/pymod/chain_mapping.py @@ -1438,6 +1438,10 @@ class ChainMapper: substructure_chem_mapping, self.n_max_naive)) + # This step can be slow so give some hints in logs + msg = "Computing initial ranking of %d chain mappings" % len(mappings) + (ost.LogWarning if len(mappings) > 10000 else ost.LogInfo)(msg) + for mapping in mappings: # chain_mapping and alns as input for lDDT computation lddt_chain_mapping = dict() diff --git a/modules/mol/alg/pymod/ligand_scoring_base.py b/modules/mol/alg/pymod/ligand_scoring_base.py index 3be4a958e5a08fe217d3e8846c053cfdcf2b4feb..19e8d617cbd7414ed3b944dee05d11a489848b63 100644 --- a/modules/mol/alg/pymod/ligand_scoring_base.py +++ b/modules/mol/alg/pymod/ligand_scoring_base.py @@ -1,10 +1,30 @@ +from contextlib import contextmanager import numpy as np import networkx from ost import mol -from ost import LogWarning, LogScript, LogVerbose, LogDebug +from ost import LogWarning, LogScript, LogInfo, LogVerbose, LogDebug, GetVerbosityLevel, PushVerbosityLevel, PopVerbosityLevel from ost.mol.alg import chain_mapping + +@contextmanager +def _SinkVerbosityLevel(n=1): + """ Context manager to temporarily reduce the verbosity level by n. + + Example usage: + with _SinkVerbosityLevel(2): + LogVerbose("Test") + Will only write "Test" in script level (2 above) + """ + PushVerbosityLevel(GetVerbosityLevel() - n) + try: + yield + except: + raise + finally: + PopVerbosityLevel() + + class LigandScorer: """ Scorer to compute various small molecule ligand (non polymer) scores. @@ -426,6 +446,7 @@ class LigandScorer: raise RuntimeError("LigandScorer._score_dir must return one in " "['+', '-']") + LogScript("Computing ligand assignment") while len(tmp) > 0: # select high coverage ligand pairs in working array coverage_thresh = max([x[1] for x in tmp]) - self.coverage_delta @@ -712,10 +733,11 @@ class LigandScorer: :type: :class:`ost.mol.alg.chain_mapping.ChainMapper` """ if self.__chain_mapper is None: - self.__chain_mapper = \ - chain_mapping.ChainMapper(self.target, - n_max_naive=1e9, - resnum_alignments=self.resnum_alignments) + with _SinkVerbosityLevel(): + self.__chain_mapper = \ + chain_mapping.ChainMapper(self.target, + n_max_naive=1e9, + resnum_alignments=self.resnum_alignments) return self.__chain_mapper @staticmethod @@ -887,7 +909,7 @@ class LigandScorer: self._state_matrix[g_idx,:] = 6 msg = "Disconnected graph observed for target ligand " msg += str(self.target_ligands[g_idx]) - LogVerbose(msg) + LogWarning(msg) for g_idx, g in enumerate(model_graphs): if not networkx.is_connected(g): @@ -895,11 +917,11 @@ class LigandScorer: self._state_matrix[:,g_idx] = 6 msg = "Disconnected graph observed for model ligand " msg += str(self.model_ligands[g_idx]) - LogVerbose(msg) + LogWarning(msg) for target_id, target_ligand in enumerate(self.target_ligands): - LogVerbose("Analyzing target ligand %s" % target_ligand) + LogInfo("Analyzing target ligand %s" % target_ligand) if self._target_ligand_states[target_id] == 4: # Disconnected graph - already updated states and reported @@ -907,7 +929,7 @@ class LigandScorer: continue for model_id, model_ligand in enumerate(self.model_ligands): - LogVerbose("Compare to model ligand %s" % model_ligand) + LogInfo("Comparing to model ligand %s" % model_ligand) ######################################################### # Compute symmetries for given target/model ligand pair # @@ -926,30 +948,30 @@ class LigandScorer: max_symmetries=self.max_symmetries, model_graph = model_graphs[model_id], target_graph = target_graphs[target_id]) - LogVerbose("Ligands %s and %s symmetry match" % ( + LogInfo("Ligands %s and %s symmetry match" % ( str(model_ligand), str(target_ligand))) except NoSymmetryError: # Ligands are different - skip - LogVerbose("No symmetry between %s and %s" % ( + LogInfo("No symmetry between %s and %s" % ( str(model_ligand), str(target_ligand))) self._state_matrix[target_id, model_id] = 1 continue except TooManySymmetriesError: # Ligands are too symmetrical - skip - LogVerbose("Too many symmetries between %s and %s" % ( + LogWarning("Too many symmetries between %s and %s" % ( str(model_ligand), str(target_ligand))) self._state_matrix[target_id, model_id] = 2 continue except NoIsomorphicSymmetryError: # Ligands are different - skip - LogVerbose("No isomorphic symmetry between %s and %s" % ( + LogInfo("No isomorphic symmetry between %s and %s" % ( str(model_ligand), str(target_ligand))) self._state_matrix[target_id, model_id] = 3 continue except DisconnectedGraphError: # this should never happen as we guard against # DisconnectedGraphError when precomputing the graph - LogVerbose("Disconnected graph observed for %s and %s" % ( + LogError("Disconnected graph observed for %s and %s" % ( str(model_ligand), str(target_ligand))) # just set both ligand states to 4 self._model_ligand_states[model_id] = 4 diff --git a/modules/mol/alg/pymod/ligand_scoring_lddtpli.py b/modules/mol/alg/pymod/ligand_scoring_lddtpli.py index 5710e3efd07d91da727424a59f050e4f39c18ba9..5ba88920d39b424b6f328fa0b2b9b3d26d6bb575 100644 --- a/modules/mol/alg/pymod/ligand_scoring_lddtpli.py +++ b/modules/mol/alg/pymod/ligand_scoring_lddtpli.py @@ -935,10 +935,11 @@ class LDDTPLIScorer(ligand_scoring_base.LigandScorer): @property def _chain_mapping_mdl(self): - if self.__chain_mapping_mdl is None: - self.__chem_mapping, self.__chem_group_alns, \ - self.__chain_mapping_mdl = \ - self._chain_mapper.GetChemMapping(self.model) + if self.__chain_mapping_mdl is None: + with ligand_scoring_base._SinkVerbosityLevel(): + self.__chem_mapping, self.__chem_group_alns, \ + self.__chain_mapping_mdl = \ + self._chain_mapper.GetChemMapping(self.model) return self.__chain_mapping_mdl # specify public interface diff --git a/modules/mol/alg/pymod/ligand_scoring_scrmsd.py b/modules/mol/alg/pymod/ligand_scoring_scrmsd.py index 56ef24a9e9cccf354e2b286aac1794ae40526ae2..5dc6e61e815c494b70641211e6bb603ed9770e17 100644 --- a/modules/mol/alg/pymod/ligand_scoring_scrmsd.py +++ b/modules/mol/alg/pymod/ligand_scoring_scrmsd.py @@ -1,11 +1,12 @@ import numpy as np -from ost import LogWarning +from ost import LogWarning, LogScript, LogInfo, LogVerbose from ost import geom from ost import mol from ost.mol.alg import ligand_scoring_base + class SCRMSDScorer(ligand_scoring_base.LigandScorer): """ :class:`LigandScorer` implementing symmetry corrected RMSD. @@ -174,6 +175,9 @@ class SCRMSDScorer(ligand_scoring_base.LigandScorer): "inconsistent_residues": list()} representations = self._get_repr(target_ligand, model_ligand) + # This step can be slow so give some hints in logs + msg = "Computing BiSyRMSD with %d chain mappings" % len(representations) + (LogWarning if len(representations) > 10000 else LogInfo)(msg) for r in representations: rmsd = _SCRMSD_symmetries(symmetries, model_ligand, @@ -231,6 +235,8 @@ class SCRMSDScorer(ligand_scoring_base.LigandScorer): if key not in self._repr: ref_bs = self._get_target_binding_site(target_ligand) + LogVerbose("%d chains are in proximity of the target ligand: %s" % ( + ref_bs.chain_count, ", ".join([c.name for c in ref_bs.chains]))) if self.full_bs_search: reprs = self._chain_mapper.GetRepr( ref_bs, self.model, inclusion_radius=self.lddt_lp_radius, @@ -262,7 +268,8 @@ class SCRMSDScorer(ligand_scoring_base.LigandScorer): h = ref_res.handle.GetHashCode() if h not in ref_residues_hashes and \ h not in ignored_residue_hashes: - view = self._chain_mapper.target.ViewForHandle(ref_res) + with ligand_scoring_base._SinkVerbosityLevel(1): + view = self._chain_mapper.target.ViewForHandle(ref_res) if view.IsValid(): h = ref_res.handle.GetHashCode() ref_residues_hashes.add(h) @@ -341,12 +348,15 @@ class SCRMSDScorer(ligand_scoring_base.LigandScorer): radius = self.model_bs_radius chains = set() for at in mdl_ligand.atoms: - close_atoms = self._chain_mapping_mdl.FindWithin(at.GetPos(), - radius) + with ligand_scoring_base._SinkVerbosityLevel(1): + close_atoms = self._chain_mapping_mdl.FindWithin(at.GetPos(), + radius) for close_at in close_atoms: chains.add(close_at.GetChain().GetName()) if len(chains) > 0: + LogVerbose("%d chains are in proximity of the model ligand: %s" % ( + len(chains), ", ".join(chains))) # the chain mapping model which only contains close chains query = "cname="