Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

develop branch completely broken with powerline-daemon #367

Closed
kovidgoyal opened this Issue · 25 comments

3 participants

@kovidgoyal
Owner

I just finished merging the current develop branch into my develop branch, and here are various issues I notice when using it with powerline daemon:

1) Tons of log spam. Everytime a client connects to the daemon the same pointless error messages are repeated. Running the daemon for even a few seconds generated a log file of ~ 16KiB, filled with repeating lines like:
2013-03-26 14:05:48,723:ERROR:WeatherSegment:Failed to get response
2013-03-26 14:05:33,264:WARNING:EmailIMAPSegment:Username and password are not configured
Presumably this is because everytime a client connects, the powerline object is recreated which presumably redoes the logging.

2) Performance in the daemon has regressed to actually being worse than for the standalone client, I dont know why that is, I'll investigate if I can find the time.

As it stands the current develop branch is unusable with powerline-daemon.

@ZyX-I
Owner
  1. The initial intention of all Powerline objects is to make them persist as long as possible. I have implemented squashing same messages and am now working at automatically reloading configuration when it was changed, but it won’t make things better if you continue to recreate Powerline objects. Cannot you just cache them, powerline-client only supplies two arguments (ext and renderer_module) that need to be used as a key and one blob (current environment) that should be handled in a special way (I guess it is better to move both environment and getcwd to segment_info, pl.environ is not such suitable for daemon as it is for vim, ipython and zsh/zpython)?
  2. I do not know the answer, but note that there are at least the following additional objects that are getting created: logger, handler and formatter for logs and PowerlineState. I would rather suggest to create logger once: after you do this you can supply existing logger to Powerline.__init__. It won’t fix the first problem though, but you in any case don’t need to recreate the logger.
@kovidgoyal
Owner
  1. If you want that to happen you need to provide some interface to go from command line arguments to rendered output that works with persistent objects. If and when you create such an interface, I'll be happy to use it. At the moment I see no way to do that, if I have missed something, feel free to point it out.
    Remember that powerline-client has to be a drop in replacement for powerline, which means that all command line arguments and options and environment and cwd has to be handled. So things like --renderer-module --width --last-exit-code etc. etc. have to work.

  2. I doubt it has anything to do with logging, the time for executing powerline-client shell left has gone to seconds from milliseconds. I suspect some more locking/threading issues.

At the moment, I am rather busy so I dont have the time to look into this. Let me know when you have implemented the required API for 1 and I will use it in the daemon and see if it improves things.

@kovidgoyal
Owner

Oh and also the new API has to deal with changes to the config files.

If I were you, I'd stop trying to make everything local and and just make logging, env vars, and cwd global parameters. That way you dont need to keep passing them around everywhere and they only need to be initialized once in the daemon. You can then use my long ago submitted patch to track the config file changes, and eveything will just work.

However, you have to live with this code base, not me, so do whatever feels best to you :)

@ZyX-I
Owner

If you want that to happen you need to provide some interface to go from command line arguments to rendered output that works with persistent objects. If and when you create such an interface, I'll be happy to use it. At the moment I see no way to do that, if I have missed something, feel free to point it out.

For arguments it was already done, segment_info=args in scripts/powerline in render call is there for this reason. But environment updates currently can only be done with powerline.renderer.pl.environ.update which is not good, especially considering that it is needed for some threaded segments (which in current state just will not receive the updates, even when you recreate Powerline object).

Remember that powerline-client has to be a drop in replacement for powerline, which means that all command line arguments and options and environment and cwd has to be handled. So things like --renderer-module --width --last-exit-code etc. etc. have to work.

ext and --renderer_module are to be parts of cache key. Everything else is .renderer.render argument.

If I were you, I'd stop trying to make everything local and and just make logging, env vars, and cwd global parameters. That way you dont need to keep passing them around everywhere and they only need to be initialized once in the daemon. You can then use my long ago submitted patch to track the config file changes, and eveything will just work.

You have different environment variables from different clients and threads that need to use them. You cannot make them global. Logger can be one for all instances if you create and supply it. How do you imagine initialization of them once if they are different in each client and you don’t know when each of them is polled?

Oh and also the new API has to deal with changes to the config files.

AFAIK you have config cache, but you don’t have something to reload configuration in vim or ipython, do you?

@ZyX-I
Owner

Note that as threaded segments will not use the updates in any case (unless you update global os.environ) you can start using existing API right now. Passing cwd right now is just the same bad thing: assigning to powerline.renderer.pl.getcwd or writing function that gets cwd from some global. All will be moved to segment_info, leaving new pl responsible only for logging.

@ZyX-I
Owner

I am imprecise: VCS segments use updated pl.getcwd for calculating key, but they ignore environment (which only is to be fixed) and in any case separate thread can receive updates for pl only via calculated key.

@kovidgoyal
Owner

You have different environment variables from different clients and threads that need to use them. You cannot make them global. Logger can be one for all instances if you create and supply it. How do you imagine initialization of them once if they are different in each client and you don’t know when each of them is polled?

Dont put every possible segment in a thread. Restrict their usage to
cases where they are actually useful, namely, where there is network I/O,
or rate monitoring and this problem goes away, alongwith the issue of new
locking/performance problems every couple of days. Threading is not a
solution for poor algorithm design. Segments that are CPU bound should
not be in threads, since the GIL means there is no benefit to
putting them in threads. Instead their algorithms need to be fixed or
they need to be removed, since running CPU intensive tasks in an always
on state monitor is not acceptable, anyway.

None of the network I/O segments or rate monitoring segments can
depend on cwd or environment variables. They canonically cannot since they
must run over an interval and there is no guarantee that env vars and
cwd, which are global in every process, despite your efforts to make
them local, remain constant over an interval. Anything that depends on
env vars or cwd must run in the main thread and must be fast. The most
obvious examples are the vcs segments. I have written code to make
them fast, so there is no need to have them in a thread anymore.

And branch coloring needs to die, it was a bad idea in the first place
and there is no way to make its resource usage acceptable for continuous
monitoring.

I'll just note that the stdlib logging module is designed to be global.
That's why you have logging.getLogger().

AFAIK you have config cache, but you don’t have something to reload configuration in vim or ipython, do you?

No, and I dont see the point of it. Adding config reloads everywhere is
just going to mean lots of extra stat() calls on systems that dont
support inotify, for extremely dubious benefit. How often do config
files actually change?

Neither vim nor ipython automatically reload their own
config files, so I see no reason why powerline running in them should.
The only reason I implemented config cache was that without it the
daemon was actually reloading and re-parsing the config files on every
client request. Hopefully, using persistent objects means that config
cache can be removed from the daemon as well. If a user wants the new
config to be used, she reloads the daemon.

Just because something can be done does not mean it should be done.
The performance and resource usage of powerline has been getting worse
and worse in the last few weeks. Hopefully, that is just temporary, but
you need to start thinking about the performance and load
characteristics of the changes you are making, before you make them.

Note that as threaded segments will not use the updates in any case
(unless you update global os.environ) you can start using existing API
right now. Passing cwd right now is just the same bad thing: assigning
to powerline.renderer.pl.getcwd or writing function that gets cwd from
some global. All will be moved to segment_info, leaving new pl
responsible only for logging.

Currently, the daemon does update both os.environ and the cwd globally.
Finalize your API, then I will make the changes, I dont have the time to
keep on making changes to the daemon code and finding problems
in the powerline code every few days, whenever the API changes.

@ZyX-I
Owner

And branch coloring needs to die, it was a bad idea in the first place
and there is no way to make its resource usage acceptable for continuous
monitoring.

It is convenient. And threading (+ using executables to avoid GIL) is the only option to make it not generate performance problems.

Neither vim nor ipython automatically reload their own
config files, so I see no reason why powerline running in them should.
The only reason I implemented config cache was that without it the
daemon was actually reloading and re-parsing the config files on every
client request. Hopefully, using persistent objects means that config
cache can be removed from the daemon as well. If a user wants the new
config to be used, she reloads the daemon.

Vim does if configured. Ask on IRC how many people resource their vimrc on BufWritePost. With both reloading is not used out-of-the-box because there is no generic way to implement it (configuration files are really programs). In ipython it is additionally much harder to do then in vim. In powerline configuration is just a bunch of static files, they generally can be reloaded thus nothing prevents us from adding reloading out-of-the-box.

Just because something can be done does not mean it should be done.
The performance and resource usage of powerline has been getting worse
and worse in the last few weeks. Hopefully, that is just temporary, but
you need to start thinking about the performance and load
characteristics of the changes you are making, before you make them.

Querying configuration each ten seconds in a separate thread generates no problems, it is not that mess with VCS segments.

@kovidgoyal
Owner

It is convenient. And threading (+ using executables to avoid GIL) is the only option to make it not generate performance problems.

I was talking about resource usage not performance. stat()ing
thousands of files several times a second is simply not an acceptable
level of system load, just to indicate if a working tree is dirty.

Querying configuration each ten seconds in a separate thread generates no problems, it is not that mess with VCS segments.

Sure it does. It causes unnecessary resource usage. powerline on my system is currently using more resources than the entire KDE plasma-desktop. You may find that acceptable, I do not.

@ZyX-I
Owner

I was talking about resource usage not performance. stat()ing
thousands of files several times a second is simply not an acceptable
level of system load, just to indicate if a working tree is dirty.

It is for user to decide. I was not the author of the idea, but I also find it convenient as the author does.

Sure it does. It causes unnecessary resource usage. powerline on my system is currently using more resources than the entire KDE plasma-desktop. You may find that acceptable, I do not.

This feature is definitely not what is causing it. With a small patch resource usage of powerline-daemon is fine:

diff --git a/powerline-daemon b/powerline-daemon
index 9c961a2..8a4fb93 100755
--- a/powerline-daemon
+++ b/powerline-daemon
@@ -45,12 +45,19 @@ parser.add_argument('--env', action='append')

 EOF = b'EOF\0\0'

+powerline_cache = {}
+
 def render(args):
     environ = {k:v for k, v in (x.partition('=')[0::2] for x in args.env)}
     cwd = environ.get('PWD', args.cwd or '/')
+    cache_key = (args.ext[0], args.renderer_module)
     os.getcwd = os.getcwdu = lambda : cwd
     os.environ = environ
-    powerline = ShellPowerline(args)
+    if cache_key in powerline_cache:
+        powerline = powerline_cache[cache_key]
+    else:
+        powerline = ShellPowerline(args)
+        powerline_cache[cache_key] = powerline
     return powerline.renderer.render(width=args.width, side=args.side)

 def eintr_retry_call(func, *args, **kwargs):
@@ -152,6 +159,8 @@ def main_loop(sock):
         while True:
             do_one(sock, read_sockets, write_sockets, result_map)
     except KeyboardInterrupt:
+        for powerline in powerline_cache.values():
+            powerline.shutdown()
         raise SystemExit(0)
     return 0

(on my branch with config reloading). Without: not. Tested against powerline-client tmux right though, it will not show me problems with repository segment.

@ZyX-I
Owner

By the way, are not you statting files in configcache much more times (as you constantly recreate powerline objects) then I do? If somebody does not like reloading in vim I will add an option to extensions configuration.

@kovidgoyal
Owner

I did not claim that reloading config files was the cause of the current resource usage problems, I said that it adds unnecessary resource utilization. If you want to design something that uses as little resource as possible, you need to avoid doing things like stating files constantly that rarely change.

By the way, are not you statting files in configcache much more times (as you constantly recreate powerline objects) then I do?

Absolutely, and I will stop doing that as soon as you finish refactoring the API for persistent objects.

@kovidgoyal
Owner

With the latest merge running Powerline.render() takes more than a second for powerline-client tmux right.

Note, this is Powerline.render() so there is no question of time taken by generating logging objects or re-creating the Powerline object. Here's a little script that I used to generate that timing info:

import time
from powerline import Powerline

pl = Powerline('tmux', interval=None)
num = 20
st = time.time()
for i in xrange(num):
    pl.render(side='right')
print ('Avg. time for render: %.2f'%((time.time()-st)/num))

which generates on my system:

Avg. time for render: 2.08

I notice no significant CPU load while running the timing script, which probably means something in the locking is broken, again.

On quitting, some of the various threaded segments generate error messages to stderr like,

Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 551, in __bootstrap_inner
  File "/usr/lib64/python2.7/threading.py", line 504, in run
  File "/home/kovid/work/vim/powerline/powerline/lib/threaded.py", line 64, in run
<type 'exceptions.TypeError'>: 'NoneType' object is not callable
@kovidgoyal
Owner

Removing the three network segments, weather, external_ip, email_imap_alert brings the time down to ~0

@Lokaltog
Owner

I'm just back after the holidays, and I haven't been able to test the latest couple of merges in real life scenarios until now. I've noticed that the threaded segments appear to be blocking the main process, e.g. with the Qtile WM statusline (whenever the weather or mail segment gets reloaded it blocks the entire thread for about a second). I'm usually not using the daemon for this, but the performance issues are probably related (Qtile runs Python in the background too so it kind of acts like the daemon - I didn't have the same performance problems before the threading features were merged).

I'm not sure if it's necessary to revert all the threading related merges just yet, but resolving this issue should be top priority. I can confirm that it only applies to IO heavy segments like kovidgoyal mentions, and removing these resolves the latency problem completely in Qtile too.

@kovidgoyal
Owner

This commit fixes it for me: kovidgoyal@1cb2df5

There may be other places it needs to be fixed as well, but that fixes it for powerline tmux right

@kovidgoyal
Owner

@Lokaltog You need to add some performance tests to the test suite.

@Lokaltog
Owner

Definitely.

I just added update_first = False to the slow WM segments (email_imap_alert and weather), and I can confirm that this completely resolves the latency issue in qtile.

@ZyX-I
Owner

@Lokaltog Can you add "update_first": false to configuration for the segments in question (to "args" dictionary)? Disabling this option in a class also disables possibility to control this by user (update_first only works when both configuration and class option allow it).

update_first option successfully defeats the purpose of threading for the sake of showing segment when it was first requested (see comment at https://github.com/ZyX-I/powerline/blob/fcc009a6f5d147ddb0f7c2f43b7ee116db0e2c8f/powerline/lib/threaded.py#L31). It should not make any difference for powerline tmux right, only for powerline-client+powerline-daemon. Neither it should make any difference for values that were requested for the second time.

@kovidgoyal
Owner

I dont think having update_first enabled for a network dependent segment is ever a good idea. If the users network is down/very slow, every request to render will cause a call to update() which might block for inderteminate amounts of time, which in turn will cause hangs in the main thread of whatever program powerline is embedded in.

@Lokaltog
Owner

@ZyX-I Sure, I just tested it to see if it would resolve the issue.

It should be mentioned that if I don't have update_first = False it delays not only the first rendering of the wm statusline, but each subsequent rendering blocks the thread for at least 1-2 seconds, and sometimes causes the wm to stop responding completely. This is partially qtile's fault since it doesn't run the statusline script in a separate thread by default, but it also seems like a symptom of an implementation problem since it's easily resolved by setting update_first = False. I don't know the internals of this option, but I'd be happy to help debugging the issue.

@ZyX-I
Owner

No need to debug, I just forgot to add

self.updated = True

to

if not self.updated:

condition.

@ZyX-I ZyX-I referenced this issue from a commit in ZyX-I/powerline
@ZyX-I ZyX-I Add forgotten self.updated set
Ref #367
6212711
@Lokaltog
Owner

Just tested with 6212711 applied, and having update_first = True still causes lag in qtile.

@ZyX-I
Owner

Just tested with 6212711 applied, and having update_first = True still causes lag in qtile.

Do not see any lags for non-first run. But I do not have qtile, thus testing in IPython using

 In[1]  from powerline import Powerline
 In[2]  p = Powerline('wm', renderer_module='pango_markup')
 In[4]  from powerline.lib.monotonic import monotonic
 In[5]  s=monotonic() ; p.render() ; print (monotonic()-s)

. For the first launch result is 1.57124980004 seconds, for the subsequent launches result is about 0.003 seconds which, I believe, is fine.

Note: email_imap_alert segment is not configured in my case. But it is based on KwThreadedSegment which is used by all vim VCS segments thus I am not expecting any problems from it.

@Lokaltog
Owner

It may be the email_imap_alert segment that screws this up. I tested and the weather segment appears to work even with update_first = True, but the email segment takes a while even on subsequent renderings:

 In[4]  s=monotonic() ; p.render() ; print (monotonic()-s)
1.0669466110011854

 In[5]  s=monotonic() ; p.render() ; print (monotonic()-s)
0.8750602299987804

 In[6]  s=monotonic() ; p.render() ; print (monotonic()-s)
0.8130072499989183
@ZyX-I ZyX-I closed this
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.