Solved

PHP time() function

Posted on 2016-08-28
12
62 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 82

Assisted Solution

by:Dave Baldwin
Dave Baldwin earned 165 total points
Comment Utility
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
Comment Utility
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 108

Assisted Solution

by:Ray Paseur
Ray Paseur earned 165 total points
Comment Utility
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
 
LVL 29

Expert Comment

by:Olaf Doschke
Comment Utility
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
Comment Utility
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
Comment Utility
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
How your wiki can always stay up-to-date

Quip doubles as a “living” wiki and a project management tool that evolves with your organization. As you finish projects in Quip, the work remains, easily accessible to all team members, new and old.
- Increase transparency
- Onboard new hires faster
- Access from mobile/offline

 

Author Comment

by:steva
Comment Utility
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
Comment Utility
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
Comment Utility
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
Comment Utility
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
Comment Utility
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
Comment Utility
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

Enabling OSINT in Activity Based Intelligence

Activity based intelligence (ABI) requires access to all available sources of data. Recorded Future allows analysts to observe structured data on the open, deep, and dark web.

Join & Write a Comment

WordPress is constantly evolving, and with each evolution appears to get better and better.  One of the big drawbacks prior to version 3 was that there was no way to be able to set up a custom menu from the backend. The Old Way Adding menus is…
Foreword (July, 2015) Since I first wrote this article, years ago, a great many more people have begun using the internet.  They are coming online from every part of the globe, learning, reading, shopping and spending money at an ever-increasing ra…
The purpose of this video is to demonstrate how to manually back up a WordPress Database. This will be demonstrated using a Windows 8 PC. The Host used will be IPage.com Log into your Hosting account. IPage will be used for demonstration : Locat…
The purpose of this video is to demonstrate how to add AdSense Ads to a WordPress Website, and how to set up WordPress to automatically place Ads in Sidebars. This will be demonstrated using a Windows 8 PC. Log into your AdSense account. : Cli…

772 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

Need Help in Real-Time?

Connect with top rated Experts

11 Experts available now in Live!

Get 1:1 Help Now