Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fixed Instrumentor generating same start time #185

Merged
merged 3 commits into from Jan 13, 2020

Conversation

@Penuvil
Copy link
Contributor

Penuvil commented Dec 13, 2019

Describe the issue (if no issue has been made)

Instrumentor clock resolution is too low and can create duplicate start times for closely executed functions.

PR impact (Make sure to add closing keywords)

List of related issues/PRs this will solve:

Impact Issue/PR
Issues this solves None
Other PRs this solves closes #175

Proposed fix (Make sure you've read on how to contribute to Hazel)

Change start and stop times to nanoseconds, static cast to long double and divide by 1000 so Chrome tracing will accept the input. Chrome tracing will not accept nanoseconds directly but will accept floating point microsecond input.

Additional context

This will fail once nanoseconds since epoch becomes too large to fit in a double.
If higher resolution than nanoseconds is needed Chrome Tracing might not be the best solution because you would have to manually manipulate start times to avoid duplicates after that.

@Penuvil

This comment has been minimized.

Copy link
Contributor Author

Penuvil commented Dec 18, 2019

@LovelySanta

This comment has been minimized.

Copy link
Collaborator

LovelySanta commented Dec 18, 2019

Similar note as I wrote in #175 (comment): Cherno has something in mind, he might fix it himself. If it still takes too long, we can always merge a PR to fix this issue.

@Penuvil

This comment has been minimized.

Copy link
Contributor Author

Penuvil commented Dec 18, 2019

Copy, no worries. I only threw it out there because of this comment...

Timer Comment

@Lecrapouille

This comment has been minimized.

Copy link

Lecrapouille commented Dec 29, 2019

@Penuvil

EDIT: sorry for multiple editions/spams. I'm reviewing the code source. I think we can add some optimizations. I summarize all my ideas. I may give a PR if needed.

Concerning the original code of Instrumentor.h:

  • It can also be nice to replace high_resolution_clock by steady_clock since high_resolution_clock is not recommended. For example, if it uses system_clock it may suffer from time forward/backward.
  • Seems to me that threadID should be size_t (and not uint32_t) when compiling with -Wconversion I have a warning.
  • With g++-8 the macro HZ_PROFILE_BEGIN_SESSION cannot accept a single param (name). Implicit filepath is an error. I have no solution for this.
  • Possible memory leak when BeginSession() is called twice: m_CurrentSession is not deleted (better to use unique_ptr or simply remove the pointer). And by the way m_OutputStream.close(); in EndSession() is useless because it's closed automatically (so no risk of file descriptor leaks with double calls of BeginSession()).
  • Get() means singleton, right ? So make the constructor Instrumentor() private (as well as methods WriteHeader and WriteFooter)
  • Place if (!m_stopped) inside Stop() to avoid double calls to Stop() because Stop() is public. Or simply remove this variable member and make Stop private.
  • In the same idea of m_stopped we can call WriteProfile() before BeginSession()or afterEndSession()with an invalidm_OutputStream`. We may add a bool for checking if the session has started.
  • I do not understand why m_profileCount++ ? This may overflow! Cannot we replace it by a bool or better add an extra comma after '}' ? I did not yet try, maybe it's still a valid json. EDIT: I tried and it is an invalid json but I hacked by adding {} in the footer and this work.
  • Why this code std::string name = result.Name; std::replace(name.begin(), name.end(), '"', '\''); and why inside WriteProfile? I think this may too CPU consuming + memory allocation. Better to move it in BeginSession to be called only once and then use char* with .c_str()
  • Following previous point: we can avoid a malloc between converting const char* to std::string concerning m_name in ProfileResult
Hazel/src/Hazel/Debug/Instrumentor.h Outdated Show resolved Hide resolved
Hazel/src/Hazel/Debug/Instrumentor.h Outdated Show resolved Hide resolved
Hazel/src/Hazel/Debug/Instrumentor.h Outdated Show resolved Hide resolved
@Lecrapouille

This comment has been minimized.

Copy link

Lecrapouille commented Dec 29, 2019

@Penuvil @LovelySanta Here my modified version https://gist.github.com/Lecrapouille/1341f9392fb79831efe5ff7f42374c54

Edit: In version 2 I restored Hazel original names and code style (version 1 was when I checked with my personal project and I did not have time to set it back. Done now). In both version I'm based on Penuvil PR. While I did not test for fast functions. I hope this will help to reduce the profiler overhead inside measurements. For the debate of long double, microseconds vs nanoseconds I cannot help because I'm a noob concerning chrono lib.

My changes (use meld editor to see diff) are:

  • Added Instrumentor::m_Started
  • Removed if (m_ProfileCount++ > 0) m_OutputStream << ","; replaced by m_OutputStream << "},";and by m_OutputStream << "{} ]}"; in WriteFooter()
  • Replaced m_OutputStream.flush(); by std::endl (some text editor failed when lines are too long)
  • Add using Clock and using TimePoint for short notations. Replaced high_resolution_clock by steady_clock
  • Move m_Stopped from ~InstrumentationTimer to Stop()
  • Remove struct ProfileResult while debatable I did to avoid copy. Feel free to restore.
  • Remove InstrumentationSession to avoid calling new and avoid the possible memory leak. I made it simple so feel free to restore/improve.
  • Implicitely fix uint32_t ThreadID vs size_t ThreadID
  • I'm not happy with std::replace(funcName.begin(), funcName.end(), '"', '\''); this makes overlay + 1 allocation. Maybe we can do
#if XXX
std::string funcName(name);
std::replace(funcName.begin(), funcName.end(), '"', '\'');
#else 
const char* funcName = name;
#endif

With XXX something like defined(__BORLANDC__) && (__BORLANDC__ >= 0x550) I give borland as example but I do not know which architecture adds "this archi shall not penalized other archis.

@Penuvil

This comment has been minimized.

Copy link
Contributor Author

Penuvil commented Jan 2, 2020

Been pretty busy with holidays and sick kids, I will look over all of this as soon as I get a chance.

@HerrDingenz

This comment has been minimized.

Copy link

HerrDingenz commented Jan 6, 2020

"Replaced m_OutputStream.flush(); by std::endl (some text editor failed when lines are too long)"

didn't you watch Jason Turners video about NOT using std::endl and instead calling std::flush on your own once work is done?

https://www.youtube.com/watch?v=GMqQOEZYVJQ&list=PLs3KjaCtOwSZ2tbuV1hx8Xz-rFZTan2J1&index=7

@Lecrapouille

This comment has been minimized.

Copy link

Lecrapouille commented Jan 6, 2020

@HerrDingenz I know that forcing a flush takes more time than letting filling the buffer until completely full which makes an automatic flush (~1024 to 4096 bytes). But you are right we can try to optimize this part. This document http://www.dil.univ-mrs.fr/~regis/prog/pdf/c-sys.4b.stdio-bufferisation.pdf describes it better than your video (sorry in french but it's the best I found yet). I summarized pages 9 and 11:

There are 3 modes of buffering:

  • unbuffered (such as stderr)
  • fully-buffered (such as stdout when not tty). Fully-buffered is flushed when one of the following conditions is met: the internal buffer is full or flush() is called or when close() is called.
  • and line-buffered (such as stdout when used as tty). Line-buffered is flushed when '\n' is met or when one of three conditions upper is met.

According to your video std::ofstream looks to be fully-buffered which is in accordance to my document. Anyway, the original code already called flushes, I just add an extra carriage return to avoid making some text editors crying when opening the file. I did nothing more! But yes, we may replace std::endl by '\n' but this not Windows compliant.

Another solution would be to store in RAM ProfileResult (with a std::dqueue ?!) and when WriteFooter() is called, convert all ProfileResults as JSON format and write lines in the file.

@Penuvil

This comment has been minimized.

Copy link
Contributor Author

Penuvil commented Jan 9, 2020

Update...
Switched to steady_clock
Got rid of static_cast
Made better use of chrono features

As pointed out there are some other issues but this PR was intended to fix the duplicate start times. I'm personally not a big fan of trying to address too many issues in one PR.

@LovelySanta

This comment has been minimized.

Copy link
Collaborator

LovelySanta commented Jan 9, 2020

This looks fine as it is to solve the issue, should we open new issues that are mentioned here, and link to this PR?

@LovelySanta LovelySanta added this to Bugfixes (awaiting merge) in Community additions Jan 9, 2020
@Penuvil

This comment has been minimized.

Copy link
Contributor Author

Penuvil commented Jan 10, 2020

Looks like the memory leak and multiple BeginSession() issues, m_ProfileCount and ThreadID are cleaned up in PR #179. I could update this PR to include the minor change to m_Stoppped if you want and the suggested change to std::replace should probably be it's own issue.

@LovelySanta

This comment has been minimized.

Copy link
Collaborator

LovelySanta commented Jan 10, 2020

Make the two seperate PR's one for m_Stopped instead of m_CurrentSession and one for the std::replace. This will be easier to resolve merge conflicts

@Lecrapouille

This comment has been minimized.

Copy link

Lecrapouille commented Jan 10, 2020

I did not notice PR 179 when I made my suggestion. It looks fine.

@LovelySanta

This comment has been minimized.

Copy link
Collaborator

LovelySanta commented Jan 12, 2020

I merged in #179, and I'm trying to resolve the merge conflicts, but whatever I do, I keep getting duplicated start times and some weird outputs.. (which is not caused by #179).

Can you resolve the merge conflicts? Or want me to push what I currently have and you go from there?

@Penuvil

This comment has been minimized.

Copy link
Contributor Author

Penuvil commented Jan 13, 2020

I will work on the conflicts and test again

@Penuvil

This comment has been minimized.

Copy link
Contributor Author

Penuvil commented Jan 13, 2020

It should be good now, test it on your rig an let me know if you have any problems.

@LovelySanta

This comment has been minimized.

Copy link
Collaborator

LovelySanta commented Jan 13, 2020

It should be good now, test it on your rig an let me know if you have any problems.

Works for me! Found my mistake: I misplaced the std::setprecision(3). I left it in the m_OutputStreaminstead of moving it over to the json stream. Tested it multiple times, not a single duplicate starting time found, and all profilers are loading and are fine (startup, runtime and shutdown).

@LovelySanta LovelySanta merged commit 0716731 into TheCherno:master Jan 13, 2020
Community additions automation moved this from Bugfixes (awaiting merge) to Merged PR's Jan 13, 2020
@Penuvil Penuvil deleted the Penuvil:original branch Jan 16, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Community additions
  
Merged PR's
4 participants
You can’t perform that action at this time.