The flushes previously existed to help ensure consistent error message output when stdout and stderr were passed to the same location. This is no longer necessary as errs() is now tied to outs().
Depends on D81156.
Differential D80803
[DebugInfo] Remove unnecessary flushes and add additional testing jhenderson on May 29 2020, 7:48 AM. Authored by
Details The flushes previously existed to help ensure consistent error message output when stdout and stderr were passed to the same location. This is no longer necessary as errs() is now tied to outs(). Depends on D81156.
Diff Detail
Event TimelineComment Actions Not sure I feel great about having these things synchronized - seems likely there's lots of error messages that get interspersed with stdout in llvm-dwarfdump and we aren't likely to get all the stdout flushed appropriately, so maybe we shouldn't start/try? If the test is flakey/unreliable due to this - perhaps it should FileCheck stdout and stderr separately rather than piping them together? (but I don't feel super strongly - I'm OK with this patch/direction if other folks think it's the right direction) Comment Actions +1. Given that the WarningHandler is configurable I don't think we should be making assumptions of what it's doing, even if printing stderr is the default. I would even go a step further and remove the existing flushes so the test don't rely on them. Comment Actions I am in favor of synchronizing stdout/stderr, i.e. when redirected to a file, making the behavior similar to a pty (line buffered). This makes stderr output in tests more relevant, i.e. we usually do 2>&1 | FileCheck, now we can check stderr output is emitted in appropriate places. However, like other opinions, I am wary of littering flush all over the code base. Also note that flushing too frequently has a performance penalty when full buffering is otherwise used. (I once made llvm-objdump -d slow due to a change to make it line buffered) Can we do something similar to D64165? Teach the warning/error (stderr) handler to flush stdout? If there is no stderr output, usual buffering (full buffering when the output is a file) is used. There is no performance penalty. Comment Actions If we're going to do it, yeah, D64165 (flushing outs() before the diagnostic, flushing the diagnostic stream after the diagnostic) would be the better direction. But even in that case - it seems it isn't consistently applied even within llvm-objdump.cpp (isn't done for command line warnings, nor for errors?) Comment Actions The idea is that some warning/error reporting facilities need outs().flush(). For llvm-objdump.cpp, reportWarning and reportError are the two utilities. It may be possible that some code path does not consistently flush outs(). We can fix them if someone observes problems. Comment Actions reportError doesn't seem to have the flushing (& also I'm not sure if it needs to use an extra raw_string_ostream - could write out to errs() directly, I think) & reportCmdLineWarning, reportCmdLineError (hmm, why are there different reportCmdLine* distinct from report*?)
Yeah, not the end of the world/fixing at least fewer places. Comment Actions reportCmdLineWarning was introduced in D66418. It reports a warning not associated with a file. Many warnings/errors are associated with a file. error: filename: .... style output is convenient when a user greps a log file. Good catch. If I add outs().flush() to reportError, no tests fail. We can add it when we see abnormal output. The logAllUnhandledErrors use can indeed be simplified.
Comment Actions I found having the error messages in different places somewhat confusing. Worse still, it seemed like occasionally they weren't consistent between being run under FileCheck and when I ran llvm-dwarfdump directly, although that might have only been tangentially related to when things were flushed. I'll take a look at moving the flushing to the error handler. It makes sense not to penalise the normal use-case, i.e. where there are no errors, by flushing unnecessarily. Comment Actions So moving the flushing to the warning handler is trickier than it first seems, because the default warning handler (which is the one used by llvm-dwarfdump) is a part of the WithColor interface now, and does not have access to the output stream used by the DWARFContext code, which may or may not be stdout. We could still go ahead and flush stdout in that function, as that will work for llvm-dwarfdump, but it's not guaranteed to achieve the intended effect in all cases. We could wrap the warning handler routine locally in the DWARFContext code to do the flushing, but it would prevent people using a non-flushing handler, which seems less than ideal. Comment Actions Having investigated further, updating the defaultWarningHandler method to flush stdout does not solve the issue, because llvm-dwarfdump actually writes to a file stream, which means the thing being flushed is not the right stream. I think the right thing to do is to have llvm-dwarfdump provide its own warning and error handler to DWARFContext. That will allow it to flush the right stream at the right time. Comment Actions Reimplemented flushing behaviour as part of the llvm-dwarfdump warning handler, as discussed. Also fixed an issue where the llvm-dwarfdump warning handler wasn't properly being copied around. I also have removed the two other existing flushes, as I believe we agree that it should be up to the handling methods to do the flushing as desired. Added @labath as a reviewer for this part, since he introduced them a few months ago. Comment Actions See rGced45978a2a5b258421590214f46848e726144b8 for where the other two flushes were introduced. I think this fix is a better fix from llvm-dwarfdump's point of view, and other clients should be updated if and when necessary. Comment Actions While I do prefer the current approach over the first revision of this path, I'm still not convinced that dwarfdump should be flushing. If you combine the streams you accept that there is no guaranteed order. Flushing is a band-aid and not a structural solution. This patch already shows that it doesn't scale. I don't think we should settle for "fix[ing] them if someone observes problems." I also don't see how that makes the errors more relevant in the tests. If they are not strict enough we should alter the error message instead of relying on the order. Comment Actions In case it wasn't clear from my previous reply, I'm totally willing to be convinced that this is the right thing to do, I just hoping for a more compelling argument. Comment Actions Looks good - I'm OK with this direction. Yeah, it's certainly likely that sort of inconsistent behavior could come from flushing issues, especially under FileCheck - I'm kind of OK with that/think a possible "right thing" would be to ensure that we don't depend on the ordering between stdout and stderr. But, yeah, this approach of flushing around diagnostics seems sustainable enough that it's an OK alternative. Comment Actions Going to revert my approval for now as @JDevlieghere 's concerns should be addressed/discussed (didn't mean to usurp his inquiry - just a race condition on feedback) @JDevlieghere I think this does show a fairly scalable solution - limited to only a couple of diagnostic handlers. But, yeah, I'm with you too - the error messages should be sufficiently self descriptive that they don't need to appear in particular places interleaved with stdout. Comment Actions I also think this approach is scalable.
Comment Actions I think this is definitely better than having scattered flushes -- thanks for working on a more systemic solution. I'm just going to throw one more idea out there. I came up with it when I was adding the original flushes. At the time I chose not to pursue it as I just wanted to get things done, but if we're going to discuss this problem in depth, I think it deserves consideration. If there's consensus that this is a good direction to go in, I'll be happy to create a patch for it
That is not really true. std::iostreams have the concept of "tied" streams, whose (I believe) sole purpose for existence is to ensure consistent ordering between cout and cerr streams. The way it works is that whenever a stream does a read or write operation from/to the backing storage, it first flushes the "tied" stream (if it has one). Normally, cin and cerr are tied to cout, and that's why patterns like cout << "Give me a number:" /* no newline*/; cin >> n; work. So, combining stdout and stderr is an issue that a lot of people considered important, and indeed there are a lot of tools out there which get it "right". llvm streams have no "tied stream" concept, and I would stipulate that this is the real reason for why we're running into the problems here. The simplest and least obtrusive way this concept could be retrofitted into the existing llvm streams is to have a new class -- let's call it tied_raw_fd_ostream. This class would inherit from raw_fd_ostream and it would take an additional constructor argument -- the "tied" stream. The only special thing it would do is that in its write_impl implementation, it would call TiedStream.flush() before doing the actual write. llvm::errs() would be of type tied_raw_fd_ostream, tied to outs(), everything else would remain unchanged. Implementing this idea should be very easy. The result won't be as flexible as the std::iostream solution, but that might actually be a good thing. And as long as an application writes only/mostly to outs(), the performance impact should be zero. If an application combines stdout and stderr a lot, then it will suffer some performance degradation, but hopefully that is not the case we need to optimize for. Comment Actions I'm happy to go for a tied stream approach. That would seem like a more scalable solution for clients that want to keep things in sync. In practice, not that much prints to stderr, so performance is probably not so critical, in my opinion. I hear @JDevlieghere's concerns about messages being self-descriptive enough to not need worrying about syncing, and I agree with the principle. Indeed, I often push for more context to be included in error messages. However, my take on it is that if error messages are near related output when the two are combined, it makes it much easier to associate one with the other, regardless of how much context there is in the message. I have often found cases in build systems etc which produce huge amounts of output for whatever reason, where the error messages end up miles away from the actual related output. Often, the stdout might say something like "Build Failed" but the related stderr error messages are several hundred lines earlier, and therefore quite hard to find. Admittedly, this is as much to do with there being too much output as it is to do with flushing, but the principle still more or less applies. In terms of the testing, I have a patch that I hope to put up for review today, to reposition the testing of the error messages in debug_line_invalid.test to be alongside their corresponding tables. The information in most (all?) of the messages is sufficient to already associate them correctly, since they contain the file offsets, but that doesn't make the test script easy to read or follow from my experience, and that's despite having written most of this test myself! Whilst I could continue to keep the errors in a single file and test that indepdendently, but with the FileCheck lines interleaved appropriately, I feel like this may get a little confusing at times. From a purely llvm-dwarfdump perspective, I think there are likely three common usages:
In the first two cases, this patch improves the issue, whilst in the third, the only thing that happens is a slight degradation in performance in the event of a warning/error being emitted. Since these should be uncommon, I think that's harmless. Testing typically will use either the first or third version (currently uses the third, but I'd like to move to the first). Comment Actions I've posted D80989 which includes test changes that rely on this flushing or something equivalent. It's also related to output ordering, but I think is slightly more general than just error messages itself. Comment Actions I've tried getting the tied_raw_fd_ostream approach to work, by tying errs() to outs() as suggested, but it doesn't work when it comes to testing D80989 (and possibly others) in lit. The problem is that llvm-dwarfdump uses a ToolOutputFile, which contains its own raw_fd_ostream pointing to stdout, with its own buffer independent of the version that is provided by outs(). Consequently, the flush triggered by writing to errs() flushes the empty outs() buffer, before writing the error message, rather than the real output buffer provided by the ToolOutputFile. I see three possible ways forward: 1) Go ahead with my existing approach as suggested in the current patch (my preference), 2) abandon the whole idea of keeping the two in sync (I don't like this idea for reasons already outlined), or 3) have raw_fd_ostream instances contructed with - (the stdout variant) actually use the outs() stream, rather than its own one - this will prevent potential weird situations where we have two independent streams with their own buffers both writing to stdout, and therefore potentially getting very weird interleaving, but I'm not sure of the knock-on effects of this yet. Thoughts? Comment Actions Hm... that is unfortunate. I think that option (3) is the most correct approach -- I find the current ToolOutputFile behavior fairly problematic -- but you're right that it can have some unexpected knock-on effects, and so I'm not sure if this patch should be predicated on that. (Incidentally, I was shocked to learn that the magicness of "-" is embedded directly into the raw_os_ostream constructor -- I would have expected this to be handled somewhere higher up (like the ToolOutputFile class, for instance).) Comment Actions I hope I didn't give the impression that I don't think it's important. I think it's really useful to have stdout and stderr for exactly the reason that James mentioned. Everything I said was weighing those benefits agains us having to maintain flushes in dwarfdump.
I really like this idea because it takes the tools out of the business of flushing and provides a structural solution to the problem. My main issue with the original patch was that it's very tricky to cover all cases and you can't sprinkle flushes until it works. Having a tied_raw_fd_ostream would solve that issue completely. As I said above I completely agree with all of this!
I strongly believe that maintainability of the tests is very important. My point was more about making sure we don't start relying on the order. But you're right, we've been doing a great job and nothing indicates that will change, so it was more of a concern than an actual problem.
My vote goes to (3) as well, though like Pavel I don't think it should block this patch. I can live with (1) for now and making (3) happen when similar issues pop up down the road. Comment Actions I'm going to focus on getting my other queued-up patches up for review before I start looking at option 3. If people are happy for this to go in, it will help with me landing the other patches I have planned, but probably isn't actually required and I can probably workaround things to some extent, so can wait if that's the preferred approach. Just let me know! Comment Actions Cool. Thanks for clearing that up. Since I started this whole thing, I felt like I should also chip in a bit. I've created D81078 to do the ToolOutputFile refactor. The changes are fairly straight-forward, and they don't break any of the in-tree tests. I have no idea whether they will break some strange out-of-tree use case (I feel it's relatively safe though the potential for it is definitely there...), but I suppose there's only one way to find that out... Comment Actions Rebase on top of D81156. This patch now just covers removing the flushes and a bit of testing. Comment Actions IIUC,
has been resolved by D81078
The idea will be implemented in D81156. This rebased patch looks good. This comment was removed by jhenderson. |
Unneeded change after your other change landed?