• Status: Solved
  • Priority: Medium
  • Security: Public
  • Views: 105
  • Last Modified:

PHP time() function

I've created a trace system to use with WordPress where I insert  update_usermeta()  calls into the code and then look at the user meta data in phpMyAdmin for user 1.  So here's what the code looks like:

timestamp
And here's the trace:

trace
The PHP time() function I'm using is documented to bring back seconds since 1970, but it seems here to be bringing back microseconds since it certainly didn't take 185 seconds to get from line 420 to 421 of the code. Does anyone know what's going on?

Thanks
0
steva
Asked:
steva
3 Solutions
 
Dave BaldwinFixer of ProblemsCommented:
A simple echo of 'time()' twice gives either 0 or 1 seconds difference.  I don't know what would be causing the difference you are seeing.
0
 
Olaf DoschkeSoftware DeveloperCommented:
Well,

the value ranges are really seconds since 1/1/1970. A very recent value while I'm writing is 1472421085.

update_usermeta is doing what? It could simply take 180s to execute, yes. Why not? Given that numbers it's the only explanation there is.

Bye, Olaf.
0
 
Ray PaseurCommented:
It's bringing back seconds.  See this link:
https://iconoun.com/demo/strtotime.php?s=Jan+1%2C+1970+%2B+1472410109+seconds

I agree with Dave - it's confusing.  I can see no reason why two consecutive statements would have a gap of over 3 minutes, unless there was human client intervention in the process.  You should be able to personally see the delay, obviously, when running this code.
0
What does it mean to be "Always On"?

Is your cloud always on? With an Always On cloud you won't have to worry about downtime for maintenance or software application code updates, ensuring that your bottom line isn't affected.

 
Olaf DoschkeSoftware DeveloperCommented:
Wordpress documentation mentions update_user_meta(), not update_usermeta(), so what is this function all about, or is it simply an older or newer wordpress version?

https://developer.wordpress.org/reference/functions/update_user_meta/

Even assuming this should not take long, it took long. So perhaps there really was some wait state, waitiing for user confirmation, for example.

Bye, Olaf.
0
 
stevaAuthor Commented:
Ok, all sorted.  Yes,  time() brings back seconds.  Here's what we're seeing.  First, there's a problem trying to log two back to back calls, like 420 and 421 above; only the second one makes it into the database.   What we're seeing in the trace is not two calls that happened immediately after one another but one call and then - after I edited some code, walked to the kitchen and back, and ran again, the second call.  I need to be sure I delete all the DB records for a run before I make another run to avoid this kind of confusion.

Also, thanks for pointing out the update_usermeta thing.  It turns out that update_usermeta() is deprecated and now update_user_meta() is recommended.

Thanks for all the input.  I split the points.
time2.jpg
0
 
Olaf DoschkeSoftware DeveloperCommented:
So it seems like what you show is no log, just the current metadata. Like two UPDATEs in a database table record still only mean one record. If you want to log something, you rather need something always and only inserting into a table or appending new lines to a log text file.

Bye, Olaf.
0
 
stevaAuthor Commented:
The text entered into the metadata table by
                                 
update_user_meta(1, 'dbg'.time(), "R1:Initializing href to: " . $href);

Open in new window

is the log. Normallly these lines are not on top of one another, like above, but sprinkled throughout the code, showing me how control flows through the code and reporting the value of important variables at each point.  The second parameter -  'dbg' . time() - is the name of the metavariable being created. So when these are sorted in the database we see a chronological listing of all the trace points.

It turns out that time() is the wrong timestamp to use because many trace points can fire inside of a second and those will all have the same metaname so only the last one will show up in the table. I've since replaced it with microtime().
0
 
Olaf DoschkeSoftware DeveloperCommented:
OK, in retrospective it could have been a first thought these two log items are not from the same request.

Shouldn't there be a view to the log in chronological order? That should reveal these two log lines are not from the same request. Instead of using the more precise microtime, wouldn't it be better to create an identifier for the current request, so you might get a trace of the log items of a single request per this identifier?

Bye, Olaf.
0
 
stevaAuthor Commented:
Shouldn't there be a view to the log in chronological order? That should reveal these two log lines are not from the same request.

The log is chronological and seeing that one entry is 185 seconds after the other tells us  they're not from the same request since each request finishes in a few seconds.

Instead of using the more precise microtime, wouldn't it be better to create an identifier for the current request, so you might get a trace of the log items of a single request per this identifier?

It's not easy to tag each request. I just wanted to throw something together quickly that let me see the flow through the code, since echo statements don't work here.  The microtime timestamp works perfectly.
0
 
Olaf DoschkeSoftware DeveloperCommented:
Well, you have an entry point somewhere, could set a $_SESSION element and use that instead of time() or additional to time().

And if you know requests don't take that long, why did you thought so? You presented this time gap between execution of the two conscutive lines as a fact, when it wasn't. If that log is chronological, it will have two or even more couples of such logged events and those will need to be close to each other.

Anyway, solved, filed and put aside.

Bye, Olaf.
0
 
stevaAuthor Commented:
Well, you have an entry point somewhere, could set a $_SESSION element and use that instead of time() or additional to time().

No, this is WordPress and WooCommerce.  There's no nice beginning and end. There are just dozens of patches of code, little functions,  in a big functions.php file and each patch can be called any time by various "hooks' throughout the pages.  It's horrible! The log lets me see which patches are called and in what order.

And if you know requests don't take that long, why did you thought so? You presented this time gap between execution of the two consecutive lines as a fact, when it wasn't.

I really thought I was seeing microseconds, for some reason. That was the original question. Why is time() returning microseconds?
0
 
Olaf DoschkeSoftware DeveloperCommented:
While the system surely is not in your own hands fully as a self written PHP system, it has some entry point, where you can set such a global thing as a session variable element. Wordpress is not working with the concept of an intentionally long running request. See for example: https://carlalexander.ca/wordpress-adventurous-entry-points/ So one obvious entry point is index.php. Either you "hack" this itself or see what is included first from hooks or template files under your official control. It's sufficient to set some session element always, it then will only change when going through this point and is available until the next request changes that session element.

Anyway, now I understand why me saying his is seconds was helpful. Well, that's just a look into the always complete and up to date good PHP documentation on php.net.

Bye, Olaf.
0

Featured Post

Upgrade your Question Security!

Add Premium security features to your question to ensure its privacy or anonymity. Learn more about your ability to control Question Security today.

Tackle projects and never again get stuck behind a technical roadblock.
Join Now