Implement CallProfiler #259

tigercosmos · 2023-12-02T13:03:33Z

This work is based on the previous #245, and the discussion on #260

This work introduces a new profiler, called CallProfiler, which can print the profiling result of a hierarchical caller stack.

Using the macro for profiler insertion.

void Foo()
{
    modmesh::USE_CALLPROFILER_PROFILE_THIS_FUNCTION();
    // ...
}

Profiling Result
  foo1 - Total Time: 61 ms, Call Count: 1
    foo2 - Total Time: 54 ms, Call Count: 1
      foo3 - Total Time: 19 ms, Call Count: 1
  foo2 - Total Time: 54 ms, Call Count: 1
    foo3 - Total Time: 19 ms, Call Count: 1
  foo3 - Total Time: 38 ms, Call Count: 2

tigercosmos · 2023-12-02T13:04:15Z

@q40603 would you like to help review this proposal and give some feedback?

q40603 · 2023-12-02T14:42:20Z

What the proposal wants to solve

The new CallProfiler tends to complete the profiling utility by

constructing the radixTree with each node holding CallerProfile that has function name, execution name, hit count.
using an STL stack to handle the call stack execution time calculation
Using Function macro together with the profiling probe insertion

Comment:

The design of the radix tree is to replace the std::map in the existing profiling util. A user can leverage the TimeRegistry and the entry API could be replaced by the RadixTree entry API to construct the profiling result.

In this case, I think the STL stack could be avoided as the profiling probe is already on the stack frame.
From the performance perspective, I think memory alloc and dealloc could also be reduced during profiling.

@tigercosmos thanks for the proposal and using the radix tree.

tigercosmos · 2023-12-02T16:09:19Z

In this case, I think the STL stack could be avoided as the profiling probe is already on the stack frame.

I thought the current APIs not be able to get a hierarchical caller stack. Could you demonstrate how to get the same output as the example above with current APIs?

From the performance perspective, I think memory alloc and dealloc could also be reduced during profiling.

It's a good point. I think the overhead is ignorable at least when the function call takes a few milliseconds.

q40603 · 2023-12-02T18:39:56Z

@tigercosmos I just created another PR for the demo.
You may refer to profileRadixTree.hpp for more details

yungyuc · 2023-12-03T01:01:17Z

From the performance perspective, I think memory alloc and dealloc could also be reduced during profiling.

It's a good point. I think the overhead is ignorable at least when the function call takes a few milliseconds.

No it's not. It's very significant when a function is called a million times in a tight loop. A scoped profiler should not be called in a tight loop, but when it is misused in that way, we still want to get reasonable results.

For low-level helper like the profiler, we should avoid STL containers.

…stProfiler

tigercosmos · 2023-12-04T16:42:01Z

@q40603 I refer to your approach and improve the code. I would like to have your review first.

yungyuc

Use end-marking comment.
Do not prefix underscore in symbol names.
Delete constructors.

yungyuc · 2023-12-04T23:41:13Z

cpp/modmesh/toggle/callprofiler.hpp

This file is not long and it seems to be OK to put the contents in RadixTree.hpp directly.

yungyuc · 2023-12-04T23:41:49Z

cpp/modmesh/toggle/callprofiler.hpp

+    std::chrono::nanoseconds total_time; /// use nanoseconds to have higher precision
+    int call_count = 0;
+    bool is_running = false;
+};


Use end-marking comment /* end struct CallProfiler */.

yungyuc · 2023-12-04T23:42:26Z

cpp/modmesh/toggle/callprofiler.hpp

+private:
+    CallProfiler() = default;
+
+    void _print_profiling_result(const RadixTreeNode<CallerProfile> & node, const int depth, std::ostream & outstream) const


Do not prefix underscore to symbols unless you are a compiler.

And this function is long. Please put it outside class declaration.

yungyuc · 2023-12-04T23:45:18Z

cpp/modmesh/toggle/callprofiler.hpp

+class CallProfiler
+{
+public:
+    /// A singleton.


Explicitly delete constructors. (You should delete all of them.)

yungyuc · 2023-12-04T23:47:36Z

cpp/modmesh/toggle/callprofiler.hpp

+private:
+    const char * m_caller_name;
+    bool m_cancel = false;
+    CallProfiler & m_profiler;


Because of this reference member m_profiler and the const member m_caller_name, you should delete implicitly created constructors.

yungyuc · 2023-12-04T23:49:10Z

gtests/test_nopython_callprofiler.cpp

+    foo3();
+    foo3();
+
+    // Example:


I like the examples in the comments.

yungyuc

Thanks a lot. The code is getting cleaner. More issues:

CallerProfile constructor
CallProfilerTest moving to test file

yungyuc · 2023-12-05T09:37:17Z

cpp/modmesh/toggle/RadixTree.hpp

+struct CallerProfile
+{
+    CallerProfile()
+        : total_time(0)


Why don't you give it a default value and avoid this custom default constructor? By the rule of 5, if you customize one of the 5, you should explicitly spell out all of the 5.

unfortunately, I found that std::chrono::nanoseconds needs to explicitly assign 0 to have the correct behavior.
sure, I will add the other 4.

I still set them as default, not sure if it is what you want

I meant to use the default value of a member datum:

std::chrono::nanoseconds total_time = 0; /// use nanoseconds to have higher precision

You already had the following. I do not see why total_time does not use a default value.

int call_count = 0; bool is_running = false;

If you use the default value of the member datum, you do not need to spell out any of the constructors.

std::chrono::nanoseconds total_time = 0 is invalid, so I use std::chrono::nanoseconds total_time = std::chrono::nanoseconds(0);

yungyuc · 2023-12-05T09:37:46Z

cpp/modmesh/toggle/RadixTree.hpp

+    bool is_running = false;
+}; /* end struct CallerProfile */
+
+class CallProfilerTest; // for gtest


Why don't you put it in gtest file?

we cannot do that, otherwise it cannot build. If I put this line to gtests file, then we get:

RadixTree.cpp C:\Users\tiger\modmesh\cpp\modmesh/toggle/RadixTree.hpp(297,28): error C2433: 'modmesh::CallProfilerTest': 'friend' not permitted on data decla rations [C:\Users\tiger\modmesh\build\cpp\modmesh\modmesh_primary.vcxproj] C:\Users\tiger\modmesh\cpp\modmesh/toggle/RadixTree.hpp(297,28): error C4430: missing type specifier - int assumed. Note: C++ does not support default-int [C:\Users\tiger\modmesh\build\cpp\modmesh\modmesh_primary.vcxproj]

Ah, for accessing private members of CallProfiler? Ok, although I don't like it, it's not intolerable.

But I think this CallProfilerTest should be at least put in detail namespace to highlight that it is not meant as part of the API.

yungyuc · 2023-12-05T09:41:20Z

cpp/modmesh/toggle/RadixTree.hpp

+        return instance;
+    }
+
+    CallProfiler(CallProfiler const &) = delete;


It's hard to read because the default constructor is too far away from here. It's more readable to move the private default constructor here, e.g.,

private: CallProfiler() = default; public: CallProfiler(CallProfiler const &) = delete; //...

yungyuc · 2023-12-05T09:43:14Z

cpp/modmesh/toggle/RadixTree.hpp

+    void end_caller(const std::string & caller_name)
+    {
+        CallerProfile & callProfile = m_radix_tree.get_current_node()->data();
+


My personal preference is to avoid the unnecessary blank lines or even make them one-liner, e.g.,

callProfile.stop_stopwatch(); // Update profiling information m_radix_tree.move_current_to_parent(); // Pop the caller from the call stack

I feel it is more readable than

// Update profiling information callProfile.stop_stopwatch(); // Pop the caller from the call stack m_radix_tree.move_current_to_parent();

But the latter is fine. I don't have a problem with it.

sure, let me change.

I also prefer local variables to use snake_case. But in the same way, I have not a problem with the style in the local scope.

ops, I missed this one.

yungyuc

Clarify whether to use default value of member datum or spell out constructors of CallerProfile
Move CallProfilerTest to detail namespace

And please do make sure all CI including linters are OK every time.

yungyuc · 2023-12-05T10:59:46Z

cpp/modmesh/toggle/RadixTree.hpp

+    bool is_running = false;
+}; /* end struct CallerProfile */
+
+class CallProfilerTest; // for gtest


Ah, for accessing private members of CallProfiler? Ok, although I don't like it, it's not intolerable.

But I think this CallProfilerTest should be at least put in detail namespace to highlight that it is not meant as part of the API.

yungyuc · 2023-12-05T11:01:58Z

cpp/modmesh/toggle/RadixTree.hpp

+struct CallerProfile
+{
+    CallerProfile()
+        : total_time(0)


I meant to use the default value of a member datum:

std::chrono::nanoseconds total_time = 0; /// use nanoseconds to have higher precision

You already had the following. I do not see why total_time does not use a default value.

int call_count = 0; bool is_running = false;

If you use the default value of the member datum, you do not need to spell out any of the constructors.

…stProfiler

tigercosmos · 2023-12-06T00:08:09Z

there are many unnecessary commits, please squash the commits when the PR is merged.

yungyuc · 2023-12-06T00:08:52Z

@tigercosmos I saw you click the request for review. Next time when you want to request for review, please leave a global comment (not inline) with a summary of what is expected to be reviewed. The diff is not self-explaining.

tigercosmos · 2023-12-06T00:26:30Z

@yungyuc Sure, the PR is ready for review, please take a look.

The CallProfiler implementation is done and the test for it is also finished.

In addition, the aforementioned issues are all addressed.

yungyuc

End marking

yungyuc · 2023-12-06T01:43:49Z

cpp/modmesh/toggle/RadixTree.hpp

+namespace detail
+{
+class CallProfilerTest; // for gtest
+}


You forgot the end marking for the namespace

@yungyuc sorry, fixed.

tigercosmos · 2023-12-07T05:01:59Z

@yungyuc all issues are clear. Ready for review.

yungyuc

Beautiful

tigercosmos and others added 8 commits November 30, 2023 04:38

CallProfiler init

65ad817

better comment

772d7cb

fix value

ce92877

add cancel callback

47c4135

add test_reset

8fbe787

correctly init std::chrono::milliseconds

d1bc0d1

fix include

090a6ad

tmp

317cbb7

yungyuc added the performance Profiling, runtime, and memory consumption label Dec 2, 2023

q40603 mentioned this pull request Dec 2, 2023

add demo for profiling using radix tree #260

Closed

tigercosmos and others added 15 commits December 4, 2023 05:05

add get_child by string

621a2da

small fix

d94c1c0

test for callprofiler

6c7b356

support windows

adc81c7

try to make CI work

79b3354

try to fix error

4b7e36c

update

b5ad167

fix time precision

025491f

Merge branch 'testProfiler' of github.com:tigercosmos/modmesh into te…

de53ae4

…stProfiler

code review.

1b68d63

code review

49da1dd

put into detail

513ce2b

fix lint

891f08e

fix test

a9af889

add is_root

92344d4

tigercosmos and others added 4 commits December 4, 2023 17:28

update the implementation

e2ac398

update

766c0ec

fix macos test

fac22d6

fix windows naming

d5953b1

tigercosmos changed the title ~~Draft: Implement CallProfiler~~ Implement CallProfiler Dec 4, 2023

yungyuc requested changes Dec 4, 2023

View reviewed changes

tigercosmos and others added 2 commits December 5, 2023 17:52

code review

94f4140

missing include

25a3623

yungyuc requested changes Dec 5, 2023

View reviewed changes

tigercosmos added 2 commits December 5, 2023 22:09

format

e58a83b

Merge branch 'testProfiler' of github.com:tigercosmos/modmesh into te…

3ac9b1e

…stProfiler

tigercosmos requested a review from yungyuc December 6, 2023 00:06

yungyuc requested changes Dec 6, 2023

View reviewed changes

add end namespace detail

3d87ba7

tigercosmos requested a review from yungyuc December 7, 2023 05:01

yungyuc approved these changes Dec 7, 2023

View reviewed changes

yungyuc merged commit a058969 into solvcon:master Dec 7, 2023
11 checks passed

tigercosmos deleted the testProfiler branch December 7, 2023 05:10

Implement CallProfiler #259

Implement CallProfiler #259

Conversation

tigercosmos commented Dec 2, 2023 • edited Loading

tigercosmos commented Dec 2, 2023

q40603 commented Dec 2, 2023 • edited Loading

What the proposal wants to solve

Comment:

tigercosmos commented Dec 2, 2023

q40603 commented Dec 2, 2023 • edited Loading

yungyuc commented Dec 3, 2023

tigercosmos commented Dec 4, 2023

yungyuc left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yungyuc left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yungyuc left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tigercosmos commented Dec 6, 2023

yungyuc commented Dec 6, 2023 • edited Loading

tigercosmos commented Dec 6, 2023

yungyuc left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tigercosmos commented Dec 7, 2023

yungyuc left a comment

Choose a reason for hiding this comment

tigercosmos commented Dec 2, 2023 •

edited

Loading

q40603 commented Dec 2, 2023 •

edited

Loading

q40603 commented Dec 2, 2023 •

edited

Loading

yungyuc left a comment •

edited

Loading

yungyuc left a comment •

edited

Loading

yungyuc left a comment •

edited

Loading

yungyuc commented Dec 6, 2023 •

edited

Loading

yungyuc left a comment •

edited

Loading