Why doesn't FreeCAD respond in real time?

Need help, or want to share a macro? Post here!
brucethepirate
Posts: 20
Joined: Fri Apr 10, 2015 9:06 pm

Why doesn't FreeCAD respond in real time?

Postby brucethepirate » Thu Jul 16, 2015 6:46 am

Hello All:

Thanks in advance for any response:

I have a shape with many points, and I use distToShape() in loops 88 times, so my program takes something like 6 hours. So, that's about 4 minutes per calculation.

I wanted to understand the timing better, so I put in print statements before and after the call, and I even printed out the time. Here is the strange thing: Freecad NEVER responded with anything printed to the screen until the entire program was finished.

What's up with that? Why not print to screen as the print statements are executed? Is it related to how I ran the program?

Thanks,

-BTP

OS: Mac OS X
Word size of OS: 64-bit
Word size of FreeCAD: 64-bit
Version: 0.15.4671 (Git)
Branch: releases/FreeCAD-0-15
Hash: 244b3aef360841646cbfe80a1b225c8b39c8380c
Python version: 2.7.9
Qt version: 4.8.6
Coin version: 4.0.0a

Macbook Pro
Software OS X 10.8.5 (12F2501)
Processor 2.6 GHz Intel Core i5
Memory 8 GB 1600 MHz DDR3
User avatar
DeepSOIC
Posts: 7485
Joined: Fri Aug 29, 2014 12:45 am
Location: Saint-Petersburg, Russia

Re: Why doesn't FreeCAD respond in real time?

Postby DeepSOIC » Thu Jul 16, 2015 8:28 am

Hi!
This is because FreeCAD is single-threaded most of the time. Processing anything blocks event loop, so UI is not updated. There should be something to deal with it, try Gui.updateGui() for example.
ulrich1a
Posts: 1920
Joined: Sun Jul 07, 2013 12:08 pm

Re: Why doesn't FreeCAD respond in real time?

Postby ulrich1a » Thu Jul 16, 2015 5:14 pm

brucethepirate wrote:What's up with that? Why not print to screen as the print statements are executed? Is it related to how I ran the program?
I have no clue, why there is such a behavior, but I have observed it also. You can get a real-time output in the console with

Code: Select all

FreeCAD.Console.PrintMessage("rotation: " + str(i) + "\n")
You can see it also in the report window. You may need to do some settings in the preferences.

Ulrich
wmayer
Site Admin
Posts: 15500
Joined: Thu Feb 19, 2009 10:32 am

Re: Why doesn't FreeCAD respond in real time?

Postby wmayer » Thu Jul 16, 2015 5:36 pm

A trick is to start FreeCAD from the command line with "--write-log". Then all messages printed with FreeCAD.Console.PrintMessage also go to the file FreeCAD.log.
This

Code: Select all

App.ConfigGet('LoggingFileName')
shows you the absolute path to the log file. Now with a tool like "tail" you can read all messages immediately.
django013
Posts: 106
Joined: Tue Jan 13, 2015 7:51 am

Re: Why doesn't FreeCAD respond in real time?

Postby django013 » Fri Jul 17, 2015 4:32 am

... shows you the absolute path to the log file. Now with a tool like "tail" you can read all messages immediately.
That's only half of the truth.
Many logs arise after the executed command is completed.

With netgen and gmsh I used to start fc with the logging enabled, to see what's going on ...
When starting gmsh-Macro to create a mesh for selected solid, it starts gmsh-execution without any log output.
When gmsh fails (after serveral minutes of processing) gmsh call logs together with the error message.
... but non of the interesting messages arives the log output.

So manual execution of subprocesses is needed. THat makes it realy hard to track errors and understand them.
OS: Linux Debian Jessie amd64 - FC: Git Master
wmayer
Site Admin
Posts: 15500
Joined: Thu Feb 19, 2009 10:32 am

Re: Why doesn't FreeCAD respond in real time?

Postby wmayer » Fri Jul 17, 2015 8:24 am

With netgen and gmsh I used to start fc with the logging enabled, to see what's going on ...
It basically depends on how something is printed. In the main() function of FreeCAD we also redirect output to std::cout, std::cerr and std::clog to our Console class. So, if a library prints to std::cout those messages will also be written to the log file. Basically, it's also possible to redirect messages printed with printf() but this is a bit more complicated.

A completely different story is it when starting a sub-process. There the above techniques won't work. However, Qt's class QProcess offers an API to read from/write to sub-processes. I don't know if Python offers something similar.
django013
Posts: 106
Joined: Tue Jan 13, 2015 7:51 am

Re: Why doesn't FreeCAD respond in real time?

Postby django013 » Fri Jul 17, 2015 2:59 pm

It basically depends on how something is printed.
...
A completely different story is it when starting a sub-process.
Ok, I don't know python - so I have to guess ...
When I look at gmsh.FCMacro it contains a "FreeCAD.Console.PrintMessage(...)"
I would expect such messages to popup at fc python console - especially if I have the redirect checkboxes in properties checked.
... but - the message never reaches fc python console.

If I start fc in logging mode and watch the log with "tail -f ", the message appears when the subprocess has terminated. In logfile, as well as at the console, where I started fc in logmode.
So might be, that FreeCAD.Console.PrintMessage() lacks some kind of flushing of stdout.
The message, how the command is executed will be printed together with the error message from "except:"-section - both at the same time.
... but execution time is several minutes :O
OS: Linux Debian Jessie amd64 - FC: Git Master
wmayer
Site Admin
Posts: 15500
Joined: Thu Feb 19, 2009 10:32 am

Re: Why doesn't FreeCAD respond in real time?

Postby wmayer » Fri Jul 17, 2015 4:52 pm

I would expect such messages to popup at fc python console - especially if I have the redirect checkboxes in properties checked.
... but - the message never reaches fc python console.
No, these messages have nothing lost in the Python console. They go to the output window instead.
If I start fc in logging mode and watch the log with "tail -f ", the message appears when the subprocess has terminated. In logfile, as well as at the console, where I started fc in logmode.
So might be, that FreeCAD.Console.PrintMessage() lacks some kind of flushing of stdout.
Does this only happen for processes invoked with subprocess? At least the class responsible for the writing to the log file is ConsoleObserverFile and this explicitly calls flush() every time Message, Warning, Error or Log is called.
django013
Posts: 106
Joined: Tue Jan 13, 2015 7:51 am

Re: Why doesn't FreeCAD respond in real time?

Postby django013 » Fri Jul 17, 2015 6:33 pm

Does this only happen for processes invoked with subprocess?
Hm, don't know. It's the only place, where I know a processing time big enuf to distinct between before and after
At least the class responsible for the writing to the log file is ConsoleObserverFile ...
Hm, I don't know nothing about that.
The script gmsh.FCMacro does not contain an explicit log statement - or better: I didn't see such a statement.
So I guess FreeCAD.Console.PrintMessage() does the logging itself.
If all statements where serialized, as suspected in single-thread apps, the message should have arived earlier.
I tested it on a quadcore machine, so none of the waiting processes where blocked by fc-thread.
OS: Linux Debian Jessie amd64 - FC: Git Master
ulrich1a
Posts: 1920
Joined: Sun Jul 07, 2013 12:08 pm

Re: Why doesn't FreeCAD respond in real time?

Postby ulrich1a » Sat Jul 18, 2015 4:39 pm

django013 wrote:
Does this only happen for processes invoked with subprocess?


Hm, don't know. It's the only place, where I know a processing time big enuf to distinct between before and after
The FreeCAD.Console.PrintMessage() in the GMSH-Macro is called after the subprocess-command. It waits for the subprocess-command to be finished and then supplys the output.

Another call would be needed in the GmSH-Macro, something with a pipe, but I do not know, how the content of a pipe could be displayed with python.

Ulrich