Skip to main content

Uniface 9: [SOLVED] Uniface Profiling log

  • November 19, 2018
  • 3 replies
  • 1 view
Jan Cees Boogaard

[SOLVED] Uniface Profiling log

Author: gianni.sandigliano@unifacesolutions.com (gianni)

Hi Unifacers, saving a profiling log from a running uniface application is logging many attributes on each line. Three couples of values are saved without and with a _X into their names: - ELAPSED / ELAPSED_X - IDLETIME / IDLETIME_X - DBMSTIME / DBMSTIME_X Meaning for each couple of values is clear but what really differentiate the column without _X from the one including _X ? I've looked into documentation but without success... Sometimes values into _X column have a value lesser, sometimes greater sometimes equal to than the one into corrispondent column without _X into its name... Thanks in advance for any contribute. Gianni

3 replies

Jan Cees Boogaard

[SOLVED] Uniface Profiling log

Author: gianni.sandigliano@unifacesolutions.com (gianni)

Hi Unifacers, saving a profiling log from a running uniface application is logging many attributes on each line. Three couples of values are saved without and with a _X into their names: - ELAPSED / ELAPSED_X - IDLETIME / IDLETIME_X - DBMSTIME / DBMSTIME_X Meaning for each couple of values is clear but what really differentiate the column without _X from the one including _X ? I've looked into documentation but without success... Sometimes values into _X column have a value lesser, sometimes greater sometimes equal to than the one into corrispondent column without _X into its name... Thanks in advance for any contribute. Gianni

Hi Gianni, I see that you've figured it out yourself. Nice. Cool And your observations are correct. Whereby actions stands for the trigger, operation or Proc module that is called. Hope this helps. Daniel


Author: diseli (daniel.iseli@uniface.com)
Jan Cees Boogaard

[SOLVED] Uniface Profiling log

Author: gianni.sandigliano@unifacesolutions.com (gianni)

Hi Unifacers, saving a profiling log from a running uniface application is logging many attributes on each line. Three couples of values are saved without and with a _X into their names: - ELAPSED / ELAPSED_X - IDLETIME / IDLETIME_X - DBMSTIME / DBMSTIME_X Meaning for each couple of values is clear but what really differentiate the column without _X from the one including _X ? I've looked into documentation but without success... Sometimes values into _X column have a value lesser, sometimes greater sometimes equal to than the one into corrispondent column without _X into its name... Thanks in advance for any contribute. Gianni

Hi all, further inspection of various logs has clearified my question: - columns with name ending _X reports time spent in action for that specific line - columns with name NOT ending with _X reports time spent in action of that specific line plus lower levels actions Values in NON _X columns are always greater than values in _X columns; my previous definition was not completely correct. This request could be defined as solved. Gianni


Author: gianni (gianni.sandigliano@unifacesolutions.com)
Jan Cees Boogaard

[SOLVED] Uniface Profiling log

Author: gianni.sandigliano@unifacesolutions.com (gianni)

Hi Unifacers, saving a profiling log from a running uniface application is logging many attributes on each line. Three couples of values are saved without and with a _X into their names: - ELAPSED / ELAPSED_X - IDLETIME / IDLETIME_X - DBMSTIME / DBMSTIME_X Meaning for each couple of values is clear but what really differentiate the column without _X from the one including _X ? I've looked into documentation but without success... Sometimes values into _X column have a value lesser, sometimes greater sometimes equal to than the one into corrispondent column without _X into its name... Thanks in advance for any contribute. Gianni

Hi This remind me a forgotten project to show the profiling info graphically. The project converts profiling info into a DOT diagram to visualize it. It had a lot of memory problems and with repetitive triggers (for example, read) but it was able to show what is happen. This example, I think, clarifies it. Following line is extracted from this example. REC=PROFILING ; SEQ=24 ; NEST=3 ; ELAPSTIME=48 ; ELAPSTIME_X=5 ; DBMSTIME=41 ; TYPE=OPR ; MODID=oGETSTATE ; MODNAM=GETSTATE ; TRIG=OPER ; TRIGGER=OPER ; OBJTYPE=SVC ; APSNAM=ANY ; CPTNAM=USYSSTAT ; INSNAM=USYSSTAT In the middle, in red, it stands GetState trigger, which took 48 time units. 48 is the sum of own ELAPSTIME_X (5) plus children's ELAPSTIME (43). The previos line in file, shows time consumed by trigger read (USYSSTAT.getstate's child) REC=PROFILING ; SEQ=25 ; NEST=4 ; ELAPSTIME=43 ; ELAPSTIME_X=43 ; DBMSTIME=41 ; DBMSTIME_X=41 ; TYPE=TRG ; MODID=t2\\READ ; MODNAM=READ ; TRIG=_read ; TRIGGER=READ ; OBJTYPE=SVC ; APSNAM=ANY ; CPTNAM=USYSSTAT ; INSNAM=USYSSTAT ; ENTITY=USTATE ; MODEL=STATE And finally, USYSSTAT.getstate was called by HEADER.getstate and summarizes all amounts: REC=PROFILING ; SEQ=23 ; NEST=2 ; ELAPSTIME=209 ; ELAPSTIME_X=161 ; DBMSTIME=127 ; DBMSTIME_X=86 ; TYPE=TRG ; MODID=tGTST ; MODNAM=GTST ; TRIG=_getstate ; TRIGGER=GTST ; OBJTYPE=DSP ; APSNAM=ANY ; CPTNAM=HEADER ; INSNAM=HEADER who tooks a total of 209 time units (it spends 161 + 48 from USYSSTAT).   regards   Luis Vila


Author: luis.vila (luis.vila@uniface.es)
Still scrolling?
Ask a question
Terms & ConditionsAccessibility statement