Skip to content

Commit

Permalink
getenv is very slow on Windows, so I replaced most of the logging cal…
Browse files Browse the repository at this point in the history 
…ls with a macro that is disabled by default. (#2826)

getenv is very slow on Windows, so I replaced most of the logging calls with a macro that is disabled by default.

Benchmark test (used a null target to exclude rendering impact):
```
./synfig synfig-core/examples/pirates.sif -o pirates.png -t null
```

All benchmarks made on Release builds.

Windows (MSVC) before:
```
Execution time: 28.352 s
Execution time: 28.345 s
Execution time: 28.391 s
```
Avg: 28362 ms

Windows (MSVC) after:
```
Execution time: 6.140 s
Execution time: 6.341 s
Execution time: 6.201 s
```
Avg: 6227 ms
Improvement: **4.55x faster** (455%)


Windows (MinGW) before:
```
real    0m19.757s
real    0m18.605s
real    0m18.697s
```
Avg: 19019 ms

Windows (MinGW) after:
```
real    0m6.842s
real    0m6.816s
real    0m6.772s
```
Avg: 6810 ms
Improvement: **2,79x faster** (279%)


Linux before:
```
./synfig  -o pirates.png -t null  3,72s user 0,39s system 109% cpu 3,756 total
./synfig  -o pirates.png -t null  3,83s user 0,37s system 109% cpu 3,834 total
./synfig  -o pirates.png -t null  3,71s user 0,42s system 109% cpu 3,778 total
```
Average: 3789 ms

Linux after:
```
./synfig  -o pirates.png -t null  3,62s user 0,38s system 111% cpu 3,583 total
./synfig  -o pirates.png -t null  3,50s user 0,40s system 110% cpu 3,523 total
./synfig  -o pirates.png -t null  3,52s user 0,39s system 108% cpu 3,593 total
```
Average: 3566 ms
Improvement: 0,06x (6%)

macOS before:
```
./synfig synfig-core/examples/pirates.sif -o  -  2,85s user 0,31s system 108% cpu 2,928 total
./synfig synfig-core/examples/pirates.sif -o  -  2,84s user 0,32s system 108% cpu 2,911 total
./synfig synfig-core/examples/pirates.sif -o  -  2,83s user 0,31s system 108% cpu 2,898 total
```
Average: 2912 ms

macOS after:
```
./synfig synfig-core/examples/pirates.sif -o  -  2,57s user 0,31s system 108% cpu 2,642 total
./synfig synfig-core/examples/pirates.sif -o  -  2,57s user 0,31s system 109% cpu 2,642 total
./synfig synfig-core/examples/pirates.sif -o  -  2,57s user 0,31s system 108% cpu 2,641 total
```
Average: 2642 ms
Improvement: 0,1x (10%)
  • Loading branch information
@ice0
ice0 committed Sep 13, 2022
1 parent 93d8f4c commit e23b229
Show file tree
Hide file tree
Showing 95 changed files with 403 additions and 393 deletions.
12 changes: 6 additions & 6 deletions synfig-core/src/synfig/bone.cpp
View file
Expand Up @@ -63,8 +63,8 @@ Bone::Bone():
depth_(0.0),
parent_(nullptr)
{
if (getenv("SYNFIG_DEBUG_NEW_BONES"))
printf("%s:%d new bone\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_NEW_BONES",
"%s:%d new bone\n", __FILE__, __LINE__);
}

//!Constructor by origin and tip
Expand All @@ -79,8 +79,8 @@ Bone::Bone(const Point &o, const Point &t):
depth_(0.0),
parent_(nullptr)
{
if (getenv("SYNFIG_DEBUG_NEW_BONES"))
printf("%s:%d new bone\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_NEW_BONES",
"%s:%d new bone\n", __FILE__, __LINE__);
}

//!Constructor by origin, angle, length, strength, parent bone (default = no parent)
Expand All @@ -96,8 +96,8 @@ Bone::Bone(const String &n, const Point &o, const Angle &a, const Real &l, Value
depth_(0.0),
parent_(p)
{
if (getenv("SYNFIG_DEBUG_NEW_BONES"))
printf("%s:%d new bone\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_NEW_BONES",
"%s:%d new bone\n", __FILE__, __LINE__);
}

const ValueNode_Bone*
Expand Down
4 changes: 2 additions & 2 deletions synfig-core/src/synfig/canvas.cpp
View file
Expand Up @@ -105,8 +105,8 @@ Canvas::Canvas(const String &id):
void
Canvas::on_changed()
{
if (getenv("SYNFIG_DEBUG_ON_CHANGED"))
printf("%s:%d Canvas::on_changed()\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_ON_CHANGED",
"%s:%d Canvas::on_changed()\n", __FILE__, __LINE__);

is_dirty_=true;
Node::on_changed();
Expand Down
9 changes: 9 additions & 0 deletions synfig-core/src/synfig/general.h
View file
Expand Up @@ -88,6 +88,15 @@ extern void warning(const String &str);
extern void info(const char *format,...);
extern void info(const String &str);

//#define LOGGING_ENABLED
#ifdef LOGGING_ENABLED
#define DEBUG_LOG(logger, fmt, ...) if (getenv(logger)) printf(fmt __VA_OPT__(,) __VA_ARGS__);
#define DEBUG_GETENV(name) getenv(name)
#else
#define DEBUG_LOG(logger, fmt, ...) void (0)
#define DEBUG_GETENV(name) false
#endif

//! Returns absolute path to the binary
extern String get_binary_path(const String &fallback_path);

Expand Down
4 changes: 2 additions & 2 deletions synfig-core/src/synfig/layer.cpp
View file
Expand Up @@ -382,8 +382,8 @@ Layer::disconnect_dynamic_param(const String& param)
void
Layer::on_changed()
{
if (getenv("SYNFIG_DEBUG_ON_CHANGED"))
printf("%s:%d Layer::on_changed()\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_ON_CHANGED",
"%s:%d Layer::on_changed()\n", __FILE__, __LINE__);

clear_time_mark();
Node::on_changed();
Expand Down
7 changes: 5 additions & 2 deletions synfig-core/src/synfig/layers/layer_skeleton.cpp
View file
Expand Up @@ -33,6 +33,9 @@
#endif

#include "layer_skeleton.h"
#ifdef _DEBUG
#include "synfig/general.h"
#endif

#include <synfig/localization.h>

Expand Down Expand Up @@ -90,8 +93,8 @@ Layer_Skeleton::Layer_Skeleton():
#ifdef _DEBUG
Layer_Skeleton::~Layer_Skeleton()
{
if (getenv("SYNFIG_DEBUG_DESTRUCTORS"))
printf("%s:%d ~Layer_Skeleton()\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_DESTRUCTORS",
"%s:%d ~Layer_Skeleton()\n", __FILE__, __LINE__);
}
#endif

Expand Down
50 changes: 25 additions & 25 deletions synfig-core/src/synfig/loadcanvas.cpp
View file
Expand Up @@ -1852,7 +1852,7 @@ CanvasParser::parse_animated(xmlpp::Element *element,Canvas::Handle canvas)
etl::handle<LinkableValueNode>
CanvasParser::parse_linkable_value_node(xmlpp::Element *element,Canvas::Handle canvas)
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_linkable_value_node\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_linkable_value_node\n", __FILE__, __LINE__);

// Determine the type
if(!element->get_attribute("type"))
Expand All @@ -1870,7 +1870,7 @@ CanvasParser::parse_linkable_value_node(xmlpp::Element *element,Canvas::Handle c
return 0;
}

if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d creating linkable '%s' type '%s'\n", __FILE__, __LINE__, element->get_name().c_str(), type.description.name.c_str());
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d creating linkable '%s' type '%s'\n", __FILE__, __LINE__, element->get_name().c_str(), type.description.name.c_str());
handle<LinkableValueNode> value_node=ValueNodeRegistry::create(element->get_name(),type);
//handle<ValueNode> c[value_node->link_count()]; changed because of clang complain
std::vector<handle<ValueNode> > c(value_node->link_count());
Expand Down Expand Up @@ -2075,8 +2075,8 @@ CanvasParser::parse_linkable_value_node(xmlpp::Element *element,Canvas::Handle c
}

String version(canvas->get_version());
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d link_count() is %d\n", __FILE__, __LINE__, value_node->link_count());
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d value_node is %s\n", __FILE__, __LINE__, value_node->get_string().c_str());
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d link_count() is %d\n", __FILE__, __LINE__, value_node->link_count());
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d value_node is %s\n", __FILE__, __LINE__, value_node->get_string().c_str());
for (int i = 0; i < value_node->link_count(); i++)
{
if (!c[i])
Expand Down Expand Up @@ -2190,7 +2190,7 @@ CanvasParser::parse_linkable_value_node(xmlpp::Element *element,Canvas::Handle c
}
}

if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_linkable_value_node done\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_linkable_value_node done\n", __FILE__, __LINE__);
return value_node;
}

Expand Down Expand Up @@ -2549,7 +2549,7 @@ CanvasParser::parse_dynamic_list(xmlpp::Element *element,Canvas::Handle canvas)
handle<ValueNode>
CanvasParser::parse_value_node(xmlpp::Element *element,Canvas::Handle canvas)
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node\n", __FILE__, __LINE__);
handle<ValueNode> value_node;
assert(element);

Expand All @@ -2558,20 +2558,20 @@ CanvasParser::parse_value_node(xmlpp::Element *element,Canvas::Handle canvas)
if(element->get_attribute("guid"))
{
guid=GUID(element->get_attribute("guid")->get_value())^canvas->get_root()->get_guid();
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d got guid %s\n", __FILE__, __LINE__, guid.get_string().c_str());
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d and element name = '%s'\n", __FILE__, __LINE__, element->get_name().c_str());
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d got guid %s\n", __FILE__, __LINE__, guid.get_string().c_str());
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d and element name = '%s'\n", __FILE__, __LINE__, element->get_name().c_str());
value_node=guid_cast<ValueNode>(guid);
if(value_node)
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node done early\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node done early\n", __FILE__, __LINE__);
if(element->get_name()!="canvas" && ValueBase::ident_type(element->get_name()) != type_nil)
{
if (element->get_name() == "bone_valuenode")
{
ValueNode_Bone::Handle value_node_bone(ValueNode_Bone::Handle::cast_dynamic(value_node));
if (!value_node_bone)
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d bone_valuenode isn't a ValueNode_Bone? It's a placeholder?\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d bone_valuenode isn't a ValueNode_Bone? It's a placeholder?\n", __FILE__, __LINE__);
return value_node;
}

Expand All @@ -2583,10 +2583,10 @@ CanvasParser::parse_value_node(xmlpp::Element *element,Canvas::Handle canvas)
}

// If ValueBase::ident_type() recognizes the name, then we know it's a ValueBase
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d element name = '%s'\n", __FILE__, __LINE__, element->get_name().c_str());
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d element name = '%s'\n", __FILE__, __LINE__, element->get_name().c_str());
if(element->get_name()!="canvas" && ValueBase::ident_type(element->get_name()) != type_nil)
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node calls parse_value\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node calls parse_value\n", __FILE__, __LINE__);
ValueBase data=parse_value(element,canvas);

if(!data.is_valid())
Expand All @@ -2606,25 +2606,25 @@ CanvasParser::parse_value_node(xmlpp::Element *element,Canvas::Handle canvas)
else
if(element->get_name()=="hermite" || element->get_name()=="animated")
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node calls parse_animated\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node calls parse_animated\n", __FILE__, __LINE__);
value_node=parse_animated(element,canvas);
}
else
if(element->get_name()=="static_list")
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node calls parse_static_list\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node calls parse_static_list\n", __FILE__, __LINE__);
value_node=parse_static_list(element,canvas);
}
else
if(element->get_name()=="dynamic_list")
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node calls parse_dynamic_list\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node calls parse_dynamic_list\n", __FILE__, __LINE__);
value_node=parse_dynamic_list(element,canvas);
}
else
if(element->get_name()=="bline") // This is not a typo. The dynamic list parser will parse a bline.
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node calls parse_dynamic_list for bline\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node calls parse_dynamic_list for bline\n", __FILE__, __LINE__);
value_node=parse_dynamic_list(element,canvas);
}
else
Expand All @@ -2639,23 +2639,23 @@ CanvasParser::parse_value_node(xmlpp::Element *element,Canvas::Handle canvas)
else
if(ValueNodeRegistry::book().count(element->get_name()))
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node calls parse_linkable_value_node\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node calls parse_linkable_value_node\n", __FILE__, __LINE__);
value_node=parse_linkable_value_node(element,canvas);
if (!value_node)
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_linkable_value_node gave us a null valuenode\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_linkable_value_node gave us a null valuenode\n", __FILE__, __LINE__);
value_node = PlaceholderValueNode::create();
}
}
else
if(element->get_name()=="canvas")
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node calls parse_canvas\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node calls parse_canvas\n", __FILE__, __LINE__);
value_node=ValueNode_Const::create(parse_canvas(element,canvas,true));
}
else
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node doesn't know what to call\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node doesn't know what to call\n", __FILE__, __LINE__);
error_unexpected_element(element,element->get_name());
error(element, strprintf(_("Expected a ValueNode. Refer to '%s'"),
VALUENODE_COMPATIBILITY_URL));
Expand Down Expand Up @@ -2695,14 +2695,14 @@ CanvasParser::parse_value_node(xmlpp::Element *element,Canvas::Handle canvas)
}
}
value_node->set_guid(guid);
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_value_node done\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_value_node done\n", __FILE__, __LINE__);
return value_node;
}

void
CanvasParser::parse_canvas_defs(xmlpp::Element *element,Canvas::Handle canvas)
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_canvas_defs\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_canvas_defs\n", __FILE__, __LINE__);
assert(element->get_name()=="defs");
xmlpp::Element::NodeList list = element->get_children();
for(xmlpp::Element::NodeList::iterator iter = list.begin(); iter != list.end(); ++iter)
Expand All @@ -2716,13 +2716,13 @@ CanvasParser::parse_canvas_defs(xmlpp::Element *element,Canvas::Handle canvas)
else
parse_value_node(child,canvas);
}
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_canvas_defs done\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_canvas_defs done\n", __FILE__, __LINE__);
}

std::list<ValueNode::Handle>
CanvasParser::parse_canvas_bones(xmlpp::Element *element,Canvas::Handle canvas)
{
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_canvas_bones\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_canvas_bones\n", __FILE__, __LINE__);
assert(element->get_name()=="bones");
xmlpp::Element::NodeList list = element->get_children();
std::list<ValueNode::Handle> bone_list;
Expand All @@ -2736,7 +2736,7 @@ CanvasParser::parse_canvas_bones(xmlpp::Element *element,Canvas::Handle canvas)
bone_list.push_back(parse_value_node(child,canvas));
}
in_bones_section = false;
if (getenv("SYNFIG_DEBUG_LOAD_CANVAS")) printf("%s:%d parse_canvas_bones done\n", __FILE__, __LINE__);
DEBUG_LOG("SYNFIG_DEBUG_LOAD_CANVAS", "%s:%d parse_canvas_bones done\n", __FILE__, __LINE__);
return bone_list;
}

Expand Down
20 changes: 10 additions & 10 deletions synfig-core/src/synfig/node.cpp
View file
Expand Up @@ -236,16 +236,16 @@ Node::add_parent(Node* new_parent)
{
std::lock_guard<std::mutex> lock(parent_set_mutex_);

if (getenv("SYNFIG_DEBUG_NODE_PARENT_SET"))
printf("%s:%d adding %p (%s) as parent of %p (%s) (%zu -> ", __FILE__, __LINE__,
DEBUG_LOG("SYNFIG_DEBUG_NODE_PARENT_SET",
"%s:%d adding %p (%s) as parent of %p (%s) (%zu -> ", __FILE__, __LINE__,
new_parent, new_parent->get_string().c_str(),
this, get_string().c_str(),
parent_set.size());

parent_set.insert(new_parent);

if (getenv("SYNFIG_DEBUG_NODE_PARENT_SET"))
printf("%zu)\n", parent_set.size());
DEBUG_LOG("SYNFIG_DEBUG_NODE_PARENT_SET",
"%zu)\n", parent_set.size());
}

void
Expand All @@ -264,24 +264,24 @@ Node::remove_parent(Node* parent)

if(parent_set.count(parent) == 0)
{
if (getenv("SYNFIG_DEBUG_NODE_PARENT_SET"))
if (DEBUG_GETENV("SYNFIG_DEBUG_NODE_PARENT_SET"))
warning("%s:%d %p (%s) isn't in parent set of %p (%s)\n", __FILE__, __LINE__,
parent, parent->get_string().c_str(),
this, get_string().c_str());

return;
}

if (getenv("SYNFIG_DEBUG_NODE_PARENT_SET"))
printf("%s:%d removing %p (%s) from parent set of %p (%s) (%zu -> ", __FILE__, __LINE__,
DEBUG_LOG("SYNFIG_DEBUG_NODE_PARENT_SET",
"%s:%d removing %p (%s) from parent set of %p (%s) (%zu -> ", __FILE__, __LINE__,
parent, parent->get_string().c_str(),
this, get_string().c_str(),
parent_set.size());

parent_set.erase(parent);

if (getenv("SYNFIG_DEBUG_NODE_PARENT_SET"))
printf("%zu)\n", parent_set.size());
DEBUG_LOG("SYNFIG_DEBUG_NODE_PARENT_SET",
"%zu)\n", parent_set.size());
}

void
Expand Down Expand Up @@ -357,7 +357,7 @@ Node::begin_delete()
void
Node::on_changed()
{
if (getenv("SYNFIG_DEBUG_ON_CHANGED"))
if (DEBUG_GETENV("SYNFIG_DEBUG_ON_CHANGED"))
{
std::lock_guard<std::mutex> lock(parent_set_mutex_);
printf("%s:%d Node::on_changed() for %p (%s); signalling these %zd parents:\n", __FILE__, __LINE__, this, get_string().c_str(), parent_set.size());
Expand Down

0 comments on commit e23b229

Please sign in to comment.