zero elapsed time in history with certain preexec functions

zero elapsed time in history with certain preexec functions

[Michael Kaminsky]

I sent this message to zsh-users in August, but didn't see any response.
In case it fell through the cracks, I'm re-sending to zsh-workers.  Can
anyone say if this is a bug?  Is there a fix or work-around?

Note:  I re-tested everything below with "zsh -f" and the behavior is the
same.  After "zsh -f" you need to "setopt" the options list in the first
example: extendedhistory histignoredups histignorespace histnostore.

Please CC me on any responses as I'm not on the list.

Thanks,

Michael

-------------------------------------------------

I use zsh's preexec function to set the title of my terminal, similar to
many of the examples posted online.  After defining preexec, however, I
noticed that zsh wasn't recording the duration of commands anymore.
After much experimentation, I believe I've come up some simple examples
to illustrate this behavior:

   $ zsh --version
   zsh 4.3.4 (i686-pc-linux-gnu)
   $ setopt|grep hist
   extendedhistory
   histignoredups
   histignorespace
   histnostore
   $ unfunction preexec
   $ sleep 2
   $ fc -ldD |tail -1
   12004  11:16  0:02  sleep 2

(so far, so good)

   $ function preexec { echo $ZSH_VERSION }
   $ sleep 2
   4.3.4
   $ fc -ldD |tail -1
   4.3.4
   12014  11:18  0:02  sleep 2

(still good, but...)

   $ function preexec { echo $ZSH_VERSION[1] }
   4.3.4
   $ sleep 2
   4
   $ fc -ldD |tail -1
   4
   12016  11:20  0:00  sleep 2

It appears that subscripting a variable (or indexing into a zsh array)
inside of the preexec function causes zsh not to record the elapsed
time/duration of the command.  There may be other actions that trigger
this behavior.  Another quick example:

   $ function preexec() { echo $1 }
   $ sleep 2
   sleep 2
   $ fc -ldD |tail -1
   fc -ldD |tail -1
   12040  11:25  0:02  sleep 2

(but...)

   $ function preexec() { echo ${(z)1} }
   function preexec() { echo ${(z)1} }
   $ sleep 2
   sleep 2
   $ fc -ldD |tail -1
   fc -ldD | tail -1
   12044  11:27  0:00  sleep 2


Any ideas?

Michael

Re: zero elapsed time in history with certain preexec functions

[Bart Schaefer]

On Dec 25,  2:07pm, Michael Kaminsky wrote:
}
} It appears that subscripting a variable (or indexing into a zsh array)
} inside of the preexec function causes zsh not to record the elapsed
} time/duration of the command.

A time is recorded, but it's the wrong time.

The following seems to fix it, but someone more familiar with this part
of the history mechanism should check my work: 

Index: Src/hist.c
===================================================================
diff -c -r1.31 hist.c
--- Src/hist.c	26 Nov 2007 17:38:13 -0000	1.31
+++ Src/hist.c	29 Dec 2007 18:24:06 -0000
@@ -826,7 +826,7 @@
     }
     chwordpos = 0;
 
-    if (hist_ring && !hist_ring->ftim)
+    if (hist_ring && !hist_ring->ftim && !strin)
 	hist_ring->ftim = time(NULL);
     if ((dohist == 2 || (interact && isset(SHINSTDIN))) && !strin) {
 	histactive = HA_ACTIVE;


(Revision numbers are from my local CVS repository and bear no relation
to the Sourceforce repository.)

-- 

Re: zero elapsed time in history with certain preexec functions

[Peter Stephenson]

On Sat, 29 Dec 2007 10:33:07 -0800
Bart Schaefer <schaefer@brasslantern.com> wrote:
> On Dec 25,  2:07pm, Michael Kaminsky wrote:
> }
> } It appears that subscripting a variable (or indexing into a zsh array)
> } inside of the preexec function causes zsh not to record the elapsed
> } time/duration of the command.
> 
> A time is recorded, but it's the wrong time.
> 
> The following seems to fix it, but someone more familiar with this part
> of the history mechanism should check my work: 

Looks entirely reasonable, without having done more than a cursory
look.

-- 
Peter Stephenson <p.w.stephenson@ntlworld.com>
Web page now at http://homepage.ntlworld.com/p.w.stephenson/