Welcome to Experts Exchange

Add your voice to the tech community where 5M+ people, just like you, are talking about what matters.

  • Help others & share knowledge
  • Earn cash & points
  • Learn & ask questions
Solved

PHP time() function

Posted on 2016-08-28
12
86 Views
Last Modified: 2016-08-31
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
Comment
Question by:steva
12 Comments
 
LVL 83

Assisted Solution

by:Dave Baldwin
Dave Baldwin earned 165 total points
ID: 41773970
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
 
LVL 29

Accepted Solution

by:
Olaf Doschke earned 170 total points
ID: 41773976
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
 
LVL 109

Assisted Solution

by:Ray Paseur
Ray Paseur earned 165 total points
ID: 41773978
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
Announcing the Most Valuable Experts of 2016

MVEs are more concerned with the satisfaction of those they help than with the considerable points they can earn. They are the types of people you feel privileged to call colleagues. Join us in honoring this amazing group of Experts.

 
LVL 29

Expert Comment

by:Olaf Doschke
ID: 41773980
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
 

Author Comment

by:steva
ID: 41774002
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
 
LVL 29

Expert Comment

by:Olaf Doschke
ID: 41774335
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
 

Author Comment

by:steva
ID: 41774913
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
 
LVL 29

Expert Comment

by:Olaf Doschke
ID: 41777651
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
 

Author Comment

by:steva
ID: 41778331
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
 
LVL 29

Expert Comment

by:Olaf Doschke
ID: 41778400
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
 

Author Comment

by:steva
ID: 41778558
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
 
LVL 29

Expert Comment

by:Olaf Doschke
ID: 41778576
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

Free Tool: Postgres Monitoring System

A PHP and Perl based system to collect and display usage statistics from PostgreSQL databases.

One of a set of tools we are providing to everyone as a way of saying thank you for being a part of the community.

Question has a verified solution.

If you are experiencing a similar issue, please ask a related question

These days socially coordinated efforts have turned into a critical requirement for enterprises.
This article discusses how to create an extensible mechanism for linked drop downs.
The purpose of this video is to demonstrate how to Test the speed of a WordPress Website. Site Speed is an important metric of a site’s health. Slow site speed can result in viewers leaving your site quickly and not seeing your content. This…
The viewer will learn how to create and use a small PHP class to apply a watermark to an image. This video shows the viewer the setup for the PHP watermark as well as important coding language. Continue to Part 2 to learn the core code used in creat…

840 members asked questions and received personalized solutions in the past 7 days.

Join the community of 500,000 technology professionals and ask your questions.

Join & Ask a Question