8
$\begingroup$

I have an application that does a bunch of small computations, mostly Table management, and logic around loops. It takes seconds to execute. However, when I turn on debug (a variable I set for varying levels of output), which is often necessary to see how certain decisions were made, it can take 5 minutes to 15 minutes to execute. This is less than ideal, as I'm using this to aid live events in realtime.

Here, the debug function executed 9625 times in a recent execution. The function is as follows:

showDebug[debug_,thisDebug_,content_]:= Module[{}, howManyDebugs++; If[debug >= thisDebug, Print[content]; ] ];

Content can consist of a simple one-line output or a stringified table.

Per answer below, I've upgraded the code to use

showDebug[debug_,thisDebug_,content_]:= Module[{}, howManyDebugs++; If[debug >= thisDebug, WriteString["stdout",content,"\n"]; ] ];

Is there a more efficient way to capture this data than outputting to the screen?

After making the change detailed above, I've experienced a roughly 50% decrease in execution time.

Improve this question
$\endgroup$
4
  • 2
    $\begingroup$ This is hard to answer without knowing how you implemented debugging. Can you explain how you are doing it precisely, and what functions you are using to print the information? $\endgroup$ Commented Nov 9, 2014 at 4:50
  • $\begingroup$ thanks for the quick reply. Pretty basic, I just have If[debug>value,Print["stuff"<>vars]]; $\endgroup$ Commented Nov 9, 2014 at 5:36
  • $\begingroup$ Can you come up with a minimal working example to reproduce your problem? $\endgroup$ Commented Nov 9, 2014 at 6:59
  • $\begingroup$ Check Sow and Reap. $\endgroup$ Commented Nov 9, 2014 at 9:10

2 Answers 2

Reset to default
14
$\begingroup$

You have several possibilities:

  1. Instead of Printing into usual StandardForm Cell where the parsing and 2D formatting take significant processor's time you can print into plain text Cells:

    CellPrint[Cell["stuff=" <> ToString[stuff]]]]

    Upon printing, you can assign the usual "Print", "Text", "Output" or another style to such a cell without changing its rendering from plain text:

    CellPrint[Cell["stuff=" <> ToString[stuff], "Print"]]

    The plain text rendering is determined by the fact that the Cell[...] object contains a simple String as the first argument and not a BoxData object.

  2. Instead of printing into separate cells you can append the debug output into the same plain text Cell as described here:

    stuff := RandomReal[]; Do[WriteString["stdout", "stuff=" <> ToString[stuff], "\n"], {10}]

    This works extremely fast, as you can check by enabling the EvaluationCompletionAction -> {"ShowTiming"} FrontEnd option (which shows absolute timing as measured by the FrontEnd):

    SetOptions[$FrontEnd, EvaluationCompletionAction -> {"ShowTiming"}]

    On my system printing of 70000 rows takes about one second:

    screenshot

  3. Instead of printing hundreds of debug messages into Notebook try to use the Dynamic functionality for displaying necessary information.

  4. Another possibility is to accumulate the debug information only in the Kernel, and implement a browser-like interface (example) for browsing the history of the dubug messages. This method allows to avoid rendering at the evaluation time completely.

  5. Instead of printing into Notebook you can append your debugging information into a running log file using PutAppend. If you want to turn off the line wrapping in the running log file, execute the following:

    SetOptions[OpenAppend, PageWidth -> Infinity]

  6. Instead of PutAppend which opens and closes the file at every call you can use OpenAppend directly (or OpenWrite): open the running log file on the beginning, then Write the debug information to it, then Close the stream.

Improve this answer
$\endgroup$
5
  • $\begingroup$ awesome, thank you very much, I will look into putting these in place, and report back on time increases. $\endgroup$ Commented Nov 10, 2014 at 1:17
  • $\begingroup$ No output: 1.93s $\endgroup$ Commented Nov 10, 2014 at 6:01
  • 1
    $\begingroup$ With no output, 1.9s to execute. Using Print["stuff"] as I was, 370s. Using WriteString["stdout","stuff","\n"] this was reduced to 166s. Pretty solid improvement. I'll check into the others as well. $\endgroup$ Commented Nov 10, 2014 at 6:20
  • $\begingroup$ Applying option one (CelPrint), it slowed down to 850s. $\endgroup$ Commented Nov 10, 2014 at 6:53
  • $\begingroup$ Have you tried the PutAppend method? I also have added the suggestion to use OpenAppend or OpenWrite directly. $\endgroup$ Commented Nov 10, 2014 at 13:23
0
$\begingroup$

Using your improved code with WriteString I find that printing 25,000 lines is essentially instantaneous on my system, therefore I doubt that this function itself is the problem. How is it being called? What does the code surrounding it look like?

It may be that your debug function is preventing some part of your code from automatically compiling. If that is the case only a compilable method is likely to be close to as fast as your code without the debug function. However I think you will not be able to compile a function that prints in real time so I will not pursue this; I only mention it as a possible explanation for your performance issue.

Improve this answer
$\endgroup$
1
  • $\begingroup$ The code surrounding it varies a fair amount. In general I have a bunch of nested For loops and If-based flow control to represent different portions of game logic, and the debugs output current state: impacts, changes, location, etc. I've since learned that For loops are not the way to approach problems in Mathematica, but the changes are slow going. $\endgroup$ Commented Nov 10, 2014 at 17:41

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.