Showing posts with label Programming. Show all posts
Showing posts with label Programming. Show all posts

Monday, March 12, 2018

Golang: Is The Mutex Is Locked, And Finding The Line Number That Did It

Quick summary of the situation, giving enough details to highlight the problem but not giving proprietary information away...

I have a program that queries a service which in turn talks to a database. The database holds records identified by unique rowkeys. I want to read all of the records, as far as the database knows of their existence, which I can get through an API call, iterating in discrete steps.

The utility I created pulls a batch of these keys, then iterates over them one by one to determine if I want to make a call to the service to pull the whole record (I don't need to if the key was already called before or previously analyzed on a previous run of the program.)

Seems relatively simple, but this is a big database and I'm going to be running this for a long time. Also, these servers are in the same network, so the connections are pretty fast and furious...if I overestimate some capacity, I'm going to really hammer the servers and the last thing I want to do is create an internal DDoS.

To that end, this utility keeps a number of running stats using structs that are updated by the various goroutines. To keep things synced up, I use an embedded lock on the structs.

(Yeah, that's a neat feature...works like this:)

type stctMyStruct struct {
sync.Mutex
intCounter int
}

After that, it's a simple matter of instantiating a struct and using it.

var strctMyStruct stctMyStruct

strctMyStruct.Lock()
strctMyStruct.intCounter = strctMyCounter.intCounter + 1
strctMyStruct.Unlock()

Because the utility is long-running and I wanted to keep tabs on different aspects of performance, I had several structs with embedded mutexes being updated by various goroutines. Using timers in separate routines, the stats were aggregated and turned into a string of text that could be printed to the console, redirected to a file or sent to a web page (I wanted a lot of options for monitoring, obviously.)

At some point I introduced a new bug in the program. My local system was relatively slow when it came to processing the keys (it's not just iterating over them...it evaluates them, sorts some things, picks through information in the full record...) and when I transferred it to the internal network, the jump in speed accelerated exposure of a timing issue. The program output...and processing...and web page displaying the status of the utility...all froze. But the program was still running, according to process monitoring.

I first thought it was a race condition...something is getting locked and not releasing it. But how can I tell if a routine is blocked by a locked struct? Golang does not have a call that will tell you if a mutex is locked, because that would lead to a race condition. In the time it takes to make the call and get the reply, that lock could have changed status.

Okay...polling the state of mutexes is out of the question. But what isn't out of the question is tracking when a request for a lock is granted.

First I changed the struct to have an addressable member for setting the state of the lock.

type stctMyStruct struct {
lock sync.Mutex
intCounter int
}

Next I created some methods for the struct to handle the locking and unlocking.

func (strctMyStruct *stctMyStruct) LockIt(intLine int) {

chnLocksTracking <- "Requesting lock to strctMyStruct by line " +strconv.Itoa(intLine)

tmElapsed := time.Now()
strctMyStruct.lock.Lock()

defer func() {

chnLocksTracking <- "Lock granted to strctMyStruct by line " + strconv.Itoa(intLine) + " in " + time.Since(tmElapsed).String()
}()

return
}

func (strctMyStruct *stctMyStruct) UnlockIt(intLine int) {

chnLocksTracking <- "Requesting unlock to strctMyStruct by line " +strconv.Itoa(intLine)

tmElapsed := time.Now()
strctMyStruct.lock.Unlock()

defer func() {

chnLocksTracking <- "Unlock granted to strctMyStruct by line " + strconv.Itoa(intLine) + " in " + time.Since(tmElapsed).String()
}()

return
}

LockIt() and UnlockIt() methods are now added to instances of stctMyStruct. When called, the function first sends a string into a channel with a dedicated goroutine on the other end digesting and logging messages; the first acts as a notification that the caller is "going to ask for a change in the mutex."

If the struct is locked, the operation will block. Once it is available, the function returns, and in the process runs the defer function which sends the granted message down the channel along with the elapsed time to get the request granted.

How does it know about the line number?

There's actually a library function that can help with that; my problem is that it returns too much information to not be a little unwieldy. To get around that, I created a small wrapper function.

func GetLine() int {
_,_,intLine, _ := runtime.Caller(1)
return intLine
}

If you look at the documentation you can get the specifics of what is returned, but Caller() can unwind the stack a from a call by the number of steps you use as an argument and return the line number, package/module, etc...in my particular case I'm using one source file so I only needed the line number.

Using this, you can insert function calls to lock and unlock the structs as needed. I added the methods to each struct that had a mutex or rwmutex. Using them is as simple as:

strctMyStruct.LockIt(GetLine())

This solution provided a way to trace what was happening, but there is a performance cost. Defer() adds a few fractions of a second each time it's called and I used a lot of locks throughout the program which added up to a significant performance hit. Using this technique is good for debugging, but you have to decide if you want to incur the overhead or find a way to compensate for it.

So what was my lock issue?

I set the goroutine monitoring the locks to dump information to a file and traced the requests vs. granted mutex changes. There was a race condition in a function I used that summarized aggregated information; A lock near the beginning of the summary was granted, and while pulling other information, it requested another lock. The second one was an operation on a struct that was held by a process waiting to get a lock on what was being held by the beginning of the summarize function.

It was a circular resource contention. Function A held a resource that Function B wanted, and Function B had a resource function A wanted. The solution was to add more granular locking, which added more calls but in the end meant (hopefully) there would be only one struct locked at a time within a given function.

Lesson learned: when using locks, keep the calls as tight and granular as possible, and avoid overlapping locks as much as possible or you may end up with a deadlock that Go's runtime wouldn't detect!

Friday, December 22, 2017

Golang Web Server: Don't Do This

I still consider myself new to programming. The new job allows me to create a lot of small system tools using Go mostly for augmenting monitoring and create utilities to replace manual API calls using JQ and CURL with single executables created in Go. It's been a wonderful learning experience.

Sometimes I try to add some new features to utilities that are snazzy but also a bit of an experiment.

This is a bit of reflection on the design I originally used and I am not in a mood to pull out layers of source code to show what I had done, especially if no one is asking for it. But I will describe the basic design in an effort to not only avoid implementing it that way again but to warn others not to make the same design pattern mistake.

The utility is mainly a long-running process that is interrogating one of our services for database information. It gets raw data from the database, pulls some stats like record size and type, and tallies the information. Millions and millions of records.

What if, I thought, I provided a peek into what the state of the tallying is beyond what I already had showing? It would output a count of some basic information as a one-liner every thirty seconds to the console, but that wasn't good enough. I thought, why not create a web interface that would output a simple text page of information?

Go loves channels. And I had several "worker goroutines" that handled specific tasks in the tally program, passing messages to a coordination process that serialized scheduling record analysis, directing results, and monitoring the state of various workers. Breaking them up made things pretty fast once I stuck in a few tweaks here and there.

Adding a web server routine wasn't hard. Then I thought, I could just add a couple of channels to plug them into routines that held statistics.

Here's where I made what later turned into a mistake.

Instead of individual handlers, I created a single handler that took message strings via channels. The messages consisted of a random ID and a type, where the type was the page request.

The reader on the other side of the channel split the message, used a select{} to determine which page it should construct, and returned through another channel the page with that ID string prepended. The receiver on the other side would look for the message and see if the ID belonged to its request. If it wasn't the proper ID, it just re-fed it to the channel, hoping that the right recipient would pick it up later, and the next message in the channel was intended for that particular reader. Line by line the page was fed back down the channel, with the ID attached to each message, until the ID was attached to a message: "END OF PAGE", at which point the page was done and connection closed.

Don't do that.

The thing is, this seemed to work. I opened a web browser, opened the page, and it worked. I could request the different pages and it worked just fine.

It worked until one page got kind of big and I opened two web pages to the server. Something seemed to get "stuck." One of my statuses gave a snapshot of the fill state of some channels and I noticed some of the web-related channels were...throbbing? Growing huge and slipping down, as if revving up with more lines of messages than should possibly be needed. Something was getting misdirected and the lightweight speed of goroutines meant it was flooding channels with useless information.

No problem, I thought. I'll add a third field, a counter, which once it reached a certain level would simply discard the message. The web page was meant to be read by a person who was trying to get some stats on the status of this utility while it was running, not the general public...refresh the page, hopefully you'll get a working reply that time. Sloppy, but might work.

Tested again. It seemed to keep the channels from getting as clogged up, but I still had some kind of crosstalk that when pages grew larger, and it wasn't hard to create some kind of denial of service from the web server when two different pages were opened. It almost seemed as if sometimes the two pages got completely confused which tab was supposed to get what page.

Maybe it was too easy to get messages mixed up because pages were feeding line by line. I went through the page composition and instead of feeding each line through, I had the process create one big string and feed the result.

This cut down on responsiveness but increased reliability. Kind of. It was significant, but not enough to be proud of. If anyone tried pulling a web page from the utility while someone else used it there was a non-zero chance it would get a weirdly formatted page, if not a timeout.

After finishing some work on other utilities, I decided to refactor the 4 web pages into their own handlers with separate functions and move some of the information being read into global structs with mutex's for protection. Before making the change I ran a test with Bombardier, a handing web server throughput tester. The test totally choked on the channel handler architecture.

I refactored, separated out the page composition into individual handlers, and eliminated channels for web page feeding. No more IDs. No more parsing out replies. No more tracking how many times this particular message is making rounds before "expiring" it.

Bombardier hammered away on the server with no issues. Multiple tabs reading different web pages? No problem. The biggest trigger for problems, clicking back or a link to one of the other pages while a large page hadn't finished rendering, was no longer a problem.

What I wanted to do was find a way to read a URL request and use one handler to interpret what the client wanted, so I didn't need a number of individual handlers defined. I'm pretty sure I still could do that, but I think the weakness was in using channels with an associated ID to parse replies back to the client from a dedicated goroutine holding stats.

The solution I ended up using was individual functions that read from a global struct holding the current state of statistics, and this was protected with a lot of locking.

I suppose another way to do it, with channels, would be finding a way to spawn dedicated channels with each request so the replies didn't need parsing or redirecting; a channel with multiple readers has no guarantee of who is going to get the message at what point. This kind of fix seemed needlessly complicated, though.

I suppose I could also have enhanced the global statistics struct to have functions associated with it, so calls could be made that would automatically lock and reply with information requested by callers. The utility is relatively small, though, and I thought that implementing that would have been more complicated than necessary. I'm not sure if this would enhance the speed of the program, though, and may be worth trying for the learning benefit.

But what I definitely now know is not to pass web pages as composed lines with an ID tagged down a shared channel for a reader to parse and decided, "Is this line meant for me? No? Here, back into the channel you go, floating rubber ducky of information, while I read the next ducky...float away!"

Don't do that.

Sunday, November 26, 2017

StackOverflow and Newcomers

Stackoverflow (SO) is the premiere question and answer site for programmers. It's a joke now that when SO goes down, programmers go home because no work can get done. It is their mission to make life better for programmers, and the men and women working behind the scenes at SO have poured much sweat and tears into growing a useful community for programmers to share solutions to various problems encountered in their algorithm-laden lives.

That is not to say there aren't issues, though. As the site has grown (and it is bit on the huge side now) SO has had to make decisions that define (and refine) the site's character, and not all of these desicions have passed without detractors. They have also had to try addressing criticism of the site, and one of the most common criticisms seems to be related to how (un)welcoming the site can be for newcomers.

I think I can relate to this. I am not a programmer by trade, but I do try to create useful utilities for use in my day job and enjoy programming in at least a hobbyist capacity. I am not very confident in my abilities, though, and definitely do not need someone to remind me of an obvious skill gap (why do you think I'm asking the question in the first place?)

I do not have the answers regarding how to make SO more welcoming to beginners. Perhaps once a community grows to a certain point it naturally fractures into a strata of people who are skilled to a point where they aren't aware of their own bias against lesser-experienced individuals. Or maybe there are rules in the system that encourage what one person interprets to be a "man up, you snowflake!" mentality while an insecure individual interprets the same feedback system to be validation that they don't have what it takes to join with programming peers.

I suppose that when so much of the technology culture centers on a "Brogrammer" mentality rife with competition using knowledge and perceived cleverness as a ranking system, it's natural for some snark to become ingrained in interactions among programmer peers. It's not hard when reading some comments and answers to a SO question to sense a tone of judgement, that the questioner must pass some bar of having earned an answer before they may have one, something beyond the basic search of the site for the same problem before duplicating it.

There have been cases where people will take more time to criticize the questioner than it would have taken to edit or refine the question into something useful and post an answer.

Sometimes it seems you can do everything seemingly right but still fall short in someone's judgement; the ability to down vote a question while leaving no constructive feedback and incurring no penalty in the process (except to the question-asker) seems like a pretty obvious way to discourage interacting with the community for help.

Note that I'm not saying down votes are necessarily bad, although I do wonder if alternative feedback methods could be useful. I'm saying that one of the more frustrating interactions on the site, in my experience, stems from being penalized and not knowing why; if you down vote, maybe you should have to leave some constructive feedback or enhancement to fix the problem or take some penalty to your own Internet-points reputation score.

For example, I recently had trouble with an intermittent panic when exiting a Go utility and posted to StackOverflow for help. I posted a title that succinctly summarized the issue. I posted the panic message. I posted the function definition. The panic had a line number from the definition that seemed to trigger the intermittent error; I posted the specific "line X is..." followed by the line of code so there was no question what snippet triggered the panic. I tagged it with appropriate tags. There were a couple of comments, and I posted a link to another question citing some code to explain (justify?) why I implemented the function call the way I did. What happened?
I took two down votes of penalty to my reputation.

In the comments I asked if the down voters could explain what I could do to improve the question for future reference. After all, SO may be for answering questions related to your immediate problems, but it's also supposed to be of use to future questioners looking to solve similar problems. Last time I checked no one explained why they did it.

The nearest I got to helpful feedback on the down votes was from one of the helpful people who submitted an answer to my question; that person speculated that it was because I had not RTFM'd to the satisfaction of some of the other users since the problematic line was in the panic and the source code for a function call used in my definition shows it probably didn't like a nil context parameter.

So as a relatively insecure beginner, I crafted a question with lots of context, source code, and clarification, only to get dinged with damage (negative reputation) by anonymous clicks from people who couldn't leave a reason why or offer feedback on improving the reference value of the question.

It shouldn't be difficult to understand why this would be discouraging to some people, especially when the goal (I thought) was to build a useful reference for many people, not (possibly) penalize someone for not meeting some arbitrary criteria for having passed a bar of RTFM to be blessed with community membership in order to be assisted without a passive aggressive backhand.

I don't count myself as a detractor of StackOverflow. I have found help from members of their community to be invaluable. I do wonder if some of the feedback mechanisms sometimes encourages certain behaviors that deter less experienced and less thick-skinned programmers from interacting while enabling programmers with the "rock star" or "ninja brogrammer" mindset to set a less friendly tone. There comes a point where it's less commiserating and sharing with a community and more a necessary chore to solve a problem, and I suspect the gray area of that transition is where new users begin complaining about the tone of the site.

Thursday, July 20, 2017

Golang: HTTP Client Opens Too Many Sockets ("Too many open files")

This relates to a project that is work related, so I have to fuzz some of the details. But on the other hand, some details are naturally fuzzed because I have to remember some of the details and my memory is naturally fuzzy...

I'm working on a utility that is, on the surface, simple. It makes a call to an API endpoint using the http.Client, compares some quick results, and if certain conditions are met it makes a series of API calls to save the JSON responses.

The processing/checking process is carried out in a set of goroutines because the comparisons are easy to do in parallel. If the routine needs to pull a JSON reply, it calls a function that is laid out pretty much like the standard examples from the "here's how you get a web page in Go!" sites.


func GetReply(strAPI string, strServer string) string {

    // The URL to request
    strURL := strServer + /service/" + strAPI

        // Also add timeouts for connections
        tr := &http.Transport{
            Dial: (&net.Dialer{
               Timeout: 5 * time.Second,
            }).Dial,
            TLSHandshakeTimeout: 5 * time.Second,
        }
    client := &http.Client{
        Transport: tr,
        Timeout:   time.Second * 10,
    }

    // Turn it into a request
    req, err := http.NewRequest("GET", strURL, nil)
    if err != nil {
        fmt.Println("\nError forming request: " + err.Error())
        return ""
    }
    req.Header.Set("Content-Type", "application/json")
    req.Header.Set("Accept", "application/json")

    // Get the URL
    res, err := client.Do(req)
    if err != nil {
        fmt.Println("\nError reading response body: " + err.Error())
        if res != nil {
            res.Body.Close()
        }
        return ""
    }

    // What was the response status from the server?
    var strResult string
    if res.StatusCode != 200 {
        fmt.Println("\nError reading response body, status code: " + res.Status)
        if res != nil {
            res.Body.Close()
        }
        return ""
    }

    // Read the reply
    body, err := ioutil.ReadAll(res.Body)
    if err != nil {
        fmt.Println("\nError reading response body: " + err.Error())
        if res != nil {
            res.Body.Close()
        }
        return ""  
   }
    res.Body.Close()

    // Cut down on calls to convert this
    strResult = string(body)

    // Done
    return strResult

}

This is actually a modified version of what I've pulled from various tutorials and examples, adding more calls to Close() and doing a check for whether res is nil before performing that call in an error.

I also added a timeout to the client because by default it is set to 0; no timeout. As you can probably guess this version was modified while troubleshooting.

After a few hours of the application running we had alerts come in about failing functions on the production servers. When I opened logs I discovered a number of "too many files open" errors, and a developer on the call said there were over 18,000 socket connections on each of the balanced servers.

The only difference was my use of this test program, so I killed it. The socket count fell.

Welp...guess we found the cause. But why?

There are a couple basics for beginners when using http.Client requests.
1) Close the response body after reading.
2) Clients are reused.
3) If you defer a call to Close() (as this one originally did, and most tutorials show) the function should call Close() when the function returns. The modified sample I posted simply closes it after reading the Body and checking for errors.

At first I thought it was due to clients not closing; they must close in order to be re-used. I traced the execution path a dozen ways and added more explicit Close()'s in error checks...but those errors were never printing anything during the run, so errors shouldn't be causing spill of sockets.

I added timeouts to the client and dialer. While that didn't hurt and probably made things a little cleaner, it still didn't help the too many open files/sockets error.

Another lead came from a close reading of a Stack Overflow answer. The function is creating a new Transport, tr, with each call. That Transport is what holds the Clients pool for reuse. See where I'm going with that?

Another answer on that page talked about creating a global client for his functions to reuse.

The theme was scope of variables matters when dealing with what allows re-use. Because I'm hitting the same server repeatedly and the function kept re-instantiating the mechanism that was used to govern client re-use,  the number of new connections and left-open sockets ballooned.

My next move was to go to the goroutines that were in charge of processing the replies from the API endpoints and have them create Transport instances, then when they call the function they passed the Transport as a parameter.

I uploaded the program to a remote system instance and re-ran it while watching netstat on the server and the client systems. After initially ballooning to about 4,000 connections it soon settled down to well under 100 connections (using netstat |wc -l).

Takeaways:
1) Modify the default client, and maybe the transport dialer, to add sane timeouts.
2) If you're hitting the same server repeatedly, do it all within the same scope as your transport instantiation or create a transport and pass it as a parameter to functions so you optimize the re-use of the client pool
3) Check that you properly close the response body so the client can be re-used. Check in error paths that it can be properly closed without panicking.

What about separating not just the Transport, but also the Client, then passing the Client around as a parameter? I didn't test that because I wasn't sure how "goroutine-safe" that would be against race conditions, despite the one answer on that Stack Overflow that demonstrated using a global Client instance for use.  It's possible it works fine. At this point it looks like passing the Transport worked fine, though.

I'll also note that my usual self-loathing and insecurity isn't getting the better of me this time because the top answer on that question that inspired me to try this solution was the usual advice I found repeatedly in other sites and blogs (and SO answers); check that you close your response properly. It's the top answer by a significant margin. It was almost an afterthought to realize that maybe what I was doing was pummeling one particular website with multiple instantiations of Client pools so Client reuse was a minimum.

Happy HTTP Client-ing!

Thursday, July 13, 2017

Your Experiences Create Your Methods

Sounds obvious, doesn't it?

But at the same time, I feel like it's one of those things that shapes our worldview to the point where you lose sight of the fact that it's obvious; we end up taking our views for granted and ignoring why you approach problems the way you do.

(Or, perhaps worse, we ignore why other people approach problems the way they do, which in turn you react towards them in a possibly negative fashion.)

I'm thinking of this because the other day I was working with a coworker on a problem assigned to us by a manager. Without getting into too many details, one step involved a program reading a list from a text file.

The file was tens of thousands of lines; the program expected the format:
12345,string of text,state_name

The file we got was formatted:
12345,"string of text",state_abbreviation

We were coming up with a game plan and reviewing steps when the file came in, and were divvying up the work needed to get the ball rolling.

My very first thought was to write a Go program that read the file contents into a slice, range over the slice to replace the comma-quote and quote-comma with just commas, then split by comma and replace the item[2] with the full state name using a map I could copy and paste from a previous program I had worked on. Give the size of the file to work on, it shouldn't have taken too long, from my estimation.

My coworker volunteered to reformat the file. After he completed it, I asked him how he cleaned the file. His background is ostensibly in sales, although he also does programming in PHP and can create mockups and web utilities for other employees to use in pulling reports and demos, so I expected he ran it through a one- or two-line PHP filter or something similar.

He pulled up Excel, imported the file as a comma-delimited file, then showed me a formula that pulled state abbreviations-to-full-names from another spreadsheet he already had set up.

In a way the approach wasn't too different. We split the lines into fields and used what amounted to a map to do a value replace, then export the results to a new text file. But the execution was very different. His sales experiences, and having to deal with formatting reports from our system, meant the first tool he used to solve the problem was a spreadsheet (which was a faster and more efficient solution than I was going to use for a one-off reformatting job like this.)

I've been working heavily on Go-based utilities; manipulating log files, manipulating APIs, making text dance as it was processed through pipelines and sending results through databases and monitoring systems. When I saw this text file I immediately saw strings.Split and map[string]string solutions running through my head.

What other solutions are there? Tons, no doubt. Filtering through a series of AWKs and pipes and redirects...maybe PERL...maybe PHP...I know there's plenty of people who would have used Excel to import it and alter it by hand. While I'd probably argue that the manual method could be considered "wrong", I'm equally sure there are people who would have arguments why every approach considered (or used) would have been "wrong."

In the end it was the (timely) results that mattered.

So next time you see someone with a different approach to doing something, don't be quick to criticize. Think about why that person has that approach. Maybe they do know something that is more efficient. Maybe not. Sometimes it's interesting to learn how someone came to use the methods they use and you'll learn something about what it's like for people who aren't you.

Wednesday, May 31, 2017

Programming a Stargate

I've really loved using the Go language. Part of my exploration and tinkering has involved side projects where I'd pull information from outside sources, usually websites, and parse the response for the information I'm looking for.

I always try to be a good citizen for web scraping; I pull the minimum information I need, close connections once I get the response, insert delays between multiple page views, etc. I always try to put only as much load on a service as a regular user would when web browsing.

"What does that have to do with Stargates?"

I really like Stargate. SG-1, Atlantis, or Discovery, doesn't matter (except the animated series...I pretend that doesn't exist.)

Some people hate it when geeks watch movies and get nitpicky about details. "CAN'T YOU JUST ENJOY THE MOVIE?!"

Not always, no. When I enjoy something, I'm the type of person who enjoys not just the story, but the universe in which it is set; this means learning about the feasibility of that story universe. Oh, sure, there are some rules you have to accept in order for that story to work (such as faster than light travel magic handwaving or using lightsabers and not having them vaporize anything too close to the wielder since, you know, REALLY HOT PLASMA...)

One of the key bits to Stargate involves using the Stargate; the dial home device for Earth's portal was not found with the gate. The device can, however, be manually "dialed", which is what SG command does...they have a computer control massive motors that sets each of the chevrons into a lock position, as well as reading diagnostic signals from the gate.

The show handwaves a lot of this process away, but I think it's implied that someone had to program the computer to attempt dialing control and reading (and sending) signals to control the gate. It's a black box; they needed to figure out "If I do X, do I get Y?" and more importantly, "Do I get Y consistently?" (Then maybe figure out what Y means. I mean, you're screwing around with an alien device that connects to other worlds, after all...) I like to think about what it took for that person to approach that black box and coax information out of it in a way that was useful.

Getting information from these websites, designed for human interaction using a web client, is like trying to programmatically poke a stargate. In the process I've discovered that our many websites are frustrating and inconsistent (I sometimes wonder, when I just want to get a list of text to parse, how many common websites are compliant for devices used by people with poor eyesight or braille systems.)

For example, I tried looking at a way to query the status of my orders from a frequently used store site. I thought it would be simple...log in and pull the orders page. Nope. If you order too many items, you might have to query another page with more order details. Sometimes order statuses change in unexpected ways. The sort order of your items isn't always consistent, either. And those were the simpler problems I encountered...figuring out consistency in delivery estimate

I tried a similar quick command line checker for a computer parts company. Turned out they had far more order statuses than I thought they did, and alerting me to changes in that order status was an interesting exercise in false alarms when they'd abruptly change from shipped to unknown and back again.

Another mini-utility I worked on was checking validity of town locations. Pray you never have to work with FIPS...

The website I chose seemed to be fairly consistent in the format of the information. Turns out I was naive in how various towns are designated, and this website was not internally consistent in showing information in a particular order. I get all sorts of interesting but very weird results for different areas around the country.

I'm sure that if I had a dial-home device (in this case, a clear API to the websites or access to an internal database) these lookups would be more straightforward. As it stands, the closest API I can use is the same as anyone with a mouse and keyboard...parsing the web page.

While frustrating at times, I am thankful that these mini-projects have taught me a few things.

  • Websites, some of which I've routinely used, are not as standardized as I thought within their own site. I just hadn't noticed when I'm searching for particular information the items I click on to get what I'm searching for.
  • I end up rethinking a lot of parsing logic when digging and sorting through human language.
  • Web sites implement some seemingly convoluted logic for interacting with clients and I now have a new appreciation for web browsers.
  • I also have a new appreciation for the usefulness of a good API. If I start a business and there's anything that can be exposed through API, I'm making it available through an API.

Saturday, April 29, 2017

Learning By Creating Support Applications

Not long ago I started a job with a company whose primary product is a very custom application that is comprised of many smaller interoperating applications. Without getting into too much detail, the applications communicate through various APIs, many of which are not well documented.

(What follows are thoughts that are not focused solely on the new employer, but rather a set of experiences I've gathered over the years from several jobs and interactions with others in the technology field. In other words, this isn't about the current employer. It's a conglomeration of experiences, and it's my own opinion. Just figured I'd have to clarify that...)

As a company focuses on growth, there comes a time when maintenance and monitoring is moved to staff that are dedicated to those tasks so the developers no longer have to do triple duty; for the new hire tasked with pioneering that position, gathering statistics to get a feel for the behavior of their systems over time, and taking care of regular maintenance and basic troubleshooting is very daunting when there is little (or no) documentation available outlining how to get the necessary metrics for gauging the health of the system.

And it isn't just a lack of documentation that acts as an obstacle. When a software-based company is first conceived and grows, it's natural for the programmers to work on getting the product into a usable, testable state. This means overcoming problems as they arise and focusing on results, not laying framework for delegating future operations.

That fosters institutional knowledge. The more of your system that is developed in-house, the more information future maintainers must glean about your system without help of outside references. Sites like Serverfault can help when you're trying to figure out why a new deployment of Nginx won't work, but it won't be useful when a log contains output from a Java application Bob, three desks away, wrote while debugging a particular reply encountered from another subsystem's API response.

Small companies with a small number of developers may feel it is inconvenient to be interrupted by the new person's constant questions about why application A is dependant on application B, or how application C discovers a service status on server 3. As a new hire, I feel a little hesitant to approach others with these types of questions, preferring to try looking for answers through other means before taking someone else's time.

(In my opinion, if the answer is to check the source code from the repo and read that to get the answers, you may as well have hired a new programmer; recognizing a need for someone dedicated to operating and maintaining your system outside the coterie of coders is a sign that there may be a need to dedicate time to documenting and tooling the application for non-programmer use.)

How can a new hire get a grasp on this situation?

In this case, I've been writing a series of Nagios plugins specifically configured to pull metrics from the various subsystems in the company application. There are cases where I thought a simple task was actually more nuanced that first appeared; each time, I ended up discovering something more about the operation of the system, and I made sure it was documented for later reference.

Each time there's a failure case, I would make a note and start work on a new monitor so we'd know about it in the future. These monitors didn't just collect a snapshot of the current state of a service, it would gather some metric that was then sent to a database and from there plotted on a graphing application for performance monitoring.

The current product relies on database performance; some queries behave different from others, where some are straightforward and others require processing of filters. Some of my checks measure response times.

Others are querying API endpoints for replies of what the services believe are their current health states.

Some queries are pulling the status of database indexing.

In cases where the application is exposing information through Java beans, my plugins are pulling numbers from JMX and checking for values within established expectations.

In other cases, plugins are checking for the existence of files that are supposed to be regularly updated and when certain records are updated in the database.

Each of these plugins, once finished and deployed, are being documented for operation in a way that when new people are hired he or she should be able to easily find a list of how these work and gather indirect information on some aspects of the in-house application operation without programmer-level institutional knowledge.

In the case of my new position, I've gained a higher respect for the value of meta-applications in gaining insight on how a complicated system works. Having information written out or explained to you is enlightening, and I never feel that documenting how something works is a waste of time. But until you find yourself executing on that knowledge, I'm not sure you really understand the subject. Creating support applications that meaningfully interact with the system pushes knowledge into the realm of wisdom the way reading about the science of flight comes alive after building your first remote control plane.

When confronted with the task of comprehending the colossal, try learning about the limited first with applications that monitor and interact with small aspects of the system. Not only will others benefit with the support applications, but you'll benefit with the mental exercise and in the end have a better model of how everything works!

Thursday, March 23, 2017

Golang: Remember This When Using Select For Monitoring Channels

I thought I would share something that's easy to overlook when using a loop to listen for messages from channels in Go.

The following is a simple code snippet:

for {
    for a := range structOfChannels {
        select {
        case msg := <- structOfChannels[a].Chan1:
            // Something
        case msg := <- structofChannels[a].Chan2:
            // Something
        default:
        }
    }
}

All this is doing is rotating over a series of channels for a message and processing them. The default case makes sure the loop doesn't get stuck after the first iteration of "select", and the for without conditions means continue until eternity.

I noticed, when running Activity Monitor (this was using Go 1.8 on OS X) that the processor would stay near 100%. The system seemed responsive, but the processor staying that high was, to me, annoying.

The solution was simple; make the loop wait a fraction of a second each iteration.

for {

    tmTimer := time.NewTimer(time.Millisecond * 50)
    <-tmTimer.C

    for a := range structOfChannels {
        select {
        case msg := <- structOfChannels[a].Chan1:
            // Something
        case msg := <- structofChannels[a].Chan2:
            // Something
        default:
        }
    }
}

This just makes the loop wait 50 milliseconds before ranging again, a pause smaller than most humans would perceive but enough for the computer that it dropped the processor use to near nothing. 

There are a few other approaches that work, but have a similar effect. For example, if you're worried about the overhead of creating and freeing the NewTimer(), you could create a NewTicker() outside the for{} scope and keep reusing that. You can also probably lower the milliseconds to smaller values and see where the processor starts kicking up, but I'll leave that to the reader to experiment and tune.

The point is, because the system seemed responsive, it was easy to overlook the effect of a simple for{} loop used to monitor messages from goroutines and there's a possibility this could have an effect when deploying to servers. Check your performance when testing your work!

Monday, March 6, 2017

When To Use "+" And When To Use "%20": Adventures In URL Encoding

I've been working on some Go-based utilities to interact with a website application written in Java. Part of this involves, in many cases, encoding database queries that are submitted to API endpoints on the Java application and interpreting the returned results.

In the process I learned something new about encoding easier to read/more human-like strings to encoded strings for the server. Namely, the standards seem broken.

I jest, but really the trouble was a matter of "it works if you know specifically how to make it work for this case."

My workflow would involve a Curl command line from a coworker with a library of working queries he had scripted out for use in other situations. I'd take that and translate it into the utility or Nagios plugin I was writing.

I took the string used in the Curl sample and feed it into Go's url.QueryEscape(), then send it to the database endpoint with

req, err := http.NewRequest("GET", strURL+"?q="+strQuery, nil)

...which promptly spit back a syntax error. Huh?

A little digging later and I found that there are standards defining an encoded space can be either "+" or "%20". And it wasn't necessarily clear when each was acceptable, and different languages varied in the strictness of their interpretation of standards.

The first red flag here is that language encoding libraries implement these changes differently, but I still felt kind of stupid at first not knowing what I was doing wrong. My self-flagellation eased a bit when I saw this was even a bug report for Go. It didn't go anywhere in terms of changing things; the language still encoded spaces as pluses and not percent-20's, but it at least acknowledges that I'm not the only one scratching my head why it wasn't working as expected.

A more elaborate answer was found on Stack Overflow. It wasn't the top answer, although each gave some elaboration on the issue, but the best one boiled the situation down to the existence of different standards for what part of the URI was being used, and backwards compatibility meant that %20 is generally safest to use but technically the %20 should be used before the ? in a URI and + be used after the ? for denoting a space.

In my case, Go liked the + for escaping strings and eschewed the percent-20. My fix? Right after running the url.QueryEscape():

strQuery = strings.Replace(strQuery, "+", "%20", -1)

Not the most elegant, but when I submitted that strQuery, the Java application was happy!

My takeaways:
1) Something I thought was simple...feeding a string to an escape function for encoding properly to a URI format...isn't necessarily straightforward. If you have trouble, find out if your application is expecting pluses or %20's for spaces.
2) Computers are binary...it works or it doesn't. But implementations of standards are still influenced by people, and languages (and libraries) are implemented by people, so even given the constraint of binary...people still make things more complicated in practice.
3) Given the confusion of + versus %20 when searching around online, I'm not the only one having this kind of issue.
4) Just use %20. Unless I run into a specific case where the other side isn't translating %20 correctly.

Sunday, May 1, 2016

GoRoutines: Are They a Tree, or Independent?

I was working on a side project when I ran into a question regarding goroutines spawning goroutines; if you have spawn a goroutine from main() (I'll call it Offspring1), and Offspring1 spawns a goroutines called Offspring2, then Offspring1 returns(), what happens to Offspring2?

Does it die, like pruning a branch off a process tree?

Or does Offspring2 keep running?

I wrote a small test application to find out.

The Test:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
package main

import (
 "fmt"
 "time"
)

var chanRunner2 = make(chan string)
var chanRunner1 = make(chan string)
var chanStop1 = make(chan bool)

func main() {

 a := time.NewTimer(5 * time.Second)
 b := time.NewTimer(10 * time.Second)

 go Runner1()

 for {
  select {
  case <-a.C:
   chanStop1 <- true
  case strMessage := <-chanRunner1:
   fmt.Println(strMessage)
  case strMessage := <-chanRunner2:
   fmt.Println(strMessage)
  case <-b.C:
   fmt.Println("DONE!")
   return
  default:
   continue
  }
 }
}

func Runner1() {

 go Runner2()

 c := time.NewTicker(500 * time.Millisecond)

 for {
  <-c.C
  select {
  case <-chanStop1:
   return
  default:
   chanRunner1 <- "Howdy from Runner1!"
  }
 }
}

func Runner2() {

 d := time.NewTicker(500 * time.Millisecond)

 for {
  <-d.C
  chanRunner2 <- "Hello from Runner2!"
 }
}

Like my previous "let's test a theory" test applications, this one is pretty straightforward. There are two functions; Runner2(), whose only job is to create a ticker that ticks every 500 milliseconds and when that tick fires it sends "Hello from Runner2!" to a channel called chanRunner2.

Runner1() is just like Runner2(), except it first spawns Runner2() before it starts firing a slightly different message into a channel called chanRunner1 every 500 milliseconds. There is one other small addition; Runner1() listens to a channel called chanStop1 and if anything comes down the pipeline, it calls return.

Then there's main(); main() creates two timers (not tickers), one that will fire in 5 seconds and one that will fire in 10 seconds. Main() then spawns Runner1() and starts a loop listening for either a timer to fire or a message from channels chanRunner1 or chanRunner2, with a default of "continue" so the select statement keeps re-evaluating in a loop.

Expected Output:

Because of the nature of goroutines and the tickers (not timers...there's an important difference...) the output should be "Howdy from Runner1!" interspersed with "Hello from Runner2!". After 5 seconds, the first timer fires, and Runner1() calls return; either both lines stop writing to the console because Runner1() returns and kills Runner2() with it, or "Hello from Runner2!" continues for the next 5 seconds without the other message interleaved, meaning that you can kill the routine that created another goroutine without having any effect on the "grandchild" goroutine to main().

Actual Output:

Drumroll, please...

./chained_goroutines
Howdy from Runner1!
Hello from Runner2!
Howdy from Runner1!
Hello from Runner2!
Howdy from Runner1!
Hello from Runner2!
Howdy from Runner1!
Hello from Runner2!
Howdy from Runner1!
Hello from Runner2!
Howdy from Runner1!
Hello from Runner2!
Howdy from Runner1!
Hello from Runner2!
Howdy from Runner1!
Hello from Runner2!
Howdy from Runner1!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
Hello from Runner2!
DONE!

There it is; Runner2() kept running after Runner1() exited. Something to keep in mind when modeling how your application works!

Monday, April 11, 2016

GoLang: More on Mutexes (A Followup)

In my previous post I explored a little bit with sync.Mutex behavior in locking changes to a struct. I was mainly focusing on how to model the behavior in my head when trying to implement a way of locking a struct for alterations to protect it from having other goroutines alter it in the middle of an operation (which after exploring mutex behavior I discovered that it doesn't really lock the struct at all, even though it kind of nearly sort of works like that when modeling the workflow I needed.)

The fact was that the mutex acts more like a flag, and encapsulating code in a lock()/unlock() bound to a particular mutex variable seemed to be a way of isolating code from running at the same time (struct or no struct.)

Is that a more proper way to think about mutexes in Go? Let's try a simple application to find out.

// More testing on Mutex use
package main

import (
 "fmt"
 "sync"
 "time"
)

func main() {

 // The mutex to lock
 var MyLock sync.Mutex

 // Save the current time
 StartTime := time.Now()

 // Create a channel to organize text messages to the user
 chanText := make(chan string)

 // Simple counter for formatting purposes
 var boolNewline bool = false

 go func() {

  // For the next 5 seconds, output a period every tick
  chanText <- "For ~5 seconds, Process 1 is printing a '.' every 100 milliseconds!"

  // Set a simple flag
  var TriggerMessage bool = true

  // A ticker
  ticker := time.NewTicker(time.Millisecond * 100)

  // Output something with each tick
  for range ticker.C {

   // Check the time since the program started
   if time.Since(StartTime).Seconds() <= 5 {

    // It was <= 5 seconds. Print the .
    fmt.Print(".")
   }

   if time.Since(StartTime).Seconds() >= 5 && TriggerMessage {
    // A simple notification
    chanText <- "For the next ~5 seconds, the lock is going to be set for Process 1!"
    TriggerMessage = false
   }

   if time.Since(StartTime).Seconds() > 5 && time.Since(StartTime).Seconds() <= 10 {
    // Now it's time for the locked portion of the demo
    MyLock.Lock()
    // Ticker within a ticker
    ticker2 := time.NewTicker(time.Millisecond * 100)
    // What follows is a label, OutOfTicker, which will be used for a nested break statement
    // to escape the embedded ticker/if statement
   OutOfTicker:
    for range ticker2.C {
     // Run until the final runtime total (of 10 seconds)
     if time.Since(StartTime).Seconds() <= 10 {
      fmt.Print(".")
     } else {
      break OutOfTicker
     }
    }
    // Unlock and notify the user
    MyLock.Unlock()
    chanText <- "Process 1 unlocked mutex!"
   }
  }
 }()

 go func() {

  chanText <- "For ~5 seconds, Process 2 is printing a '*' every 100 milliseconds!"

  var TriggerMessage bool = true

  ticker := time.NewTicker(time.Millisecond * 100)

  for range ticker.C {

   if time.Since(StartTime).Seconds() <= 5 {

    fmt.Print("*")
   }

   if time.Since(StartTime).Seconds() >= 5 && TriggerMessage {
    chanText <- "For the next ~5 seconds, the lock is going to be set for Process 2!"
    TriggerMessage = false
   }

   if time.Since(StartTime).Seconds() > 5 && time.Since(StartTime).Seconds() <= 10 {
    MyLock.Lock()
    ticker2 := time.NewTicker(time.Millisecond * 100)
   OutOfTicker:
    for range ticker2.C {
     if time.Since(StartTime).Seconds() <= 10 {
      fmt.Print("*")
     } else {
      break OutOfTicker
     }
    }
    MyLock.Unlock()
    chanText <- "Process 2 unlocked mutex!"
   }
  }
 }()

 // And now we kill main() after a set period of time, which is 2 seconds after everything has
 // hopefully finished without issue
 timer := time.NewTimer(time.Second * 12)
 for {
  select {
  case <-timer.C:
   // Time to stop
   // Send a formatting newline and exit main()
   fmt.Print("\n")
   return
  case strMessage := <-chanText:
   // Message from the goroutines
   // boolNewLine is checked so every other line is fed a newline, just to make the text
   // to the user more readable/neat, then flips the state of boolNewLine for the next iteration
   if !boolNewline {
    fmt.Print("\n")
    fmt.Println(strMessage)
    boolNewline = true
   } else {
    fmt.Println(strMessage)
    boolNewline = false
   }
  }
 }
}

I think the code is pretty straightforward; the two goroutines are virtually identical, and the first one is heavily commented. Main() starts off with a declaration of a mutex called MyLock, then grabs the current time (as a time.Time type) stored as StartTime, since the application is going to run for X number of seconds from the start of execution.

For the sake of simplifying formatting, I opted to create a channel for the two goroutines to send information back to main() and let main() be responsible for serializing and formatting the text. Because goroutines output is indeterministic, controlled by the scheduler, letting them dump text to fmt.Print() can be less predictable and a little less readable. Channels kind of filter the information; text is sent into the channel, they will be kind of serialized until the reader on the other side (in main()) pulls the message off the channel and processes it. One thing to note - you can affect the indeterministic nature of goroutine execution by not reading from the channel in main(); since it's a blocking operation (unless you use a channel with buffers), if you were to do something like time.Sleep() in main() where it should read more from the channel, you'll stop the goroutines from working when they try to send something down the channel again.

The last thing I set up was a small boolean variable to again help with some formatting of text.

After the spawning of the goroutines, main() declares a timer that will run for 12 seconds because the demo from the goroutines should finish in 10. After that is the loop that checks for either the timer to tick ("We're done!") or a message from the channel. The message flips the boolean between true and false because if I didn't, some of the text would get tacked on the end of the line of "." or "*" from the goroutines and it made it look bad. Because there's two goroutines, it was fairly simple to use the boolean to say "add a newline before printing this" and flipping the state so the next message was just, "Print the message."

The goroutines are fairly simple too; most of their logic is a matter of evaluating time so they knew when to lock and unlock. They notify the channel that they're going to run for 5 seconds and create a boolean flag for their change in message later, then create a periodic 100ms ticker.

Then it's time to listen to the ticker. If the time is less than 5 seconds since launch, it just sends a character to the console.

If the time is greater than 5 seconds and my boolean flag is set, it sends the message that for the next 5 seconds it's going to set the lock, then turns off that message from reappearing using the boolean flag since otherwise it may keep printing it every 100 milliseconds, or once the later logic is through it might occasionally spill over again.

(At this point I could probably have turned off the ticker within the next inner loop so that wouldn't be re-evaluated or set some conditional that would have invalidated it in later runs. I used the flag because it was relatively simple while I iterated through my tests for the blog post. Point is, there's more than one way to have achieved this, probably every way has some merit, but for this purpose it worked.)

The next bit runs if the time is between 5 and 10 seconds. The goroutines set the lock and create a new timer, then I use a label (OutOfTicker) above an "inner evaluation" loop for the new timer. That small inner lop runs until 10 seconds since the launch of the program, then breaks out of the inner loops to the scope of the label. At that point they'll unlock the mutex and send a message down the channel that the mutex is unlocked.

What does the output look like?

go build && ./mutex_testering2

For ~5 seconds, Process 1 is printing a '.' every 100 milliseconds!
For ~5 seconds, Process 2 is printing a '*' every 100 milliseconds!
.*.*.*.*.*.**..*.**.*..*.*.**..**.*..*.*.*.*.*.*.**.*.*.*..**..**..**..**.*..**..**..*.*.*.*.*.*.*
For the next ~5 seconds, the lock is going to be set for Process 1!
For the next ~5 seconds, the lock is going to be set for Process 2!
.................................................
Process 1 unlocked mutex!
Process 2 unlocked mutex!

go build && ./mutex_testering2

For ~5 seconds, Process 1 is printing a '.' every 100 milliseconds!
For ~5 seconds, Process 2 is printing a '*' every 100 milliseconds!
.*.*.*.**..*.*.*.*.**..**..*.*.**.*..**.*.*..**..**.*.*..*.**..**.*..**..*.*.*.*.*.*.**.*..**.*..*
For the next ~5 seconds, the lock is going to be set for Process 2!
For the next ~5 seconds, the lock is going to be set for Process 1!
*************************************************
Process 2 unlocked mutex!
Process 1 unlocked mutex!

I included two runs to show that the scheduling was random enough that sometimes the first goroutine has the lock and runs, and sometimes the second one gets to run with the lock. Because they're time restricted, they stop trying to run around the same time, so there's no blip from the opposite goroutine when the mutexes are released. Although it might be possible? Maybe?

Conclusion

Thinking of mutexes as a way to lock a struct worked for my particular purpose when trying to imagine the workflow in my particular application at the time, but probably better to think of mutexes as a way of having your code check a variable to see if it's okay to run anything contained between the Lock() and Unlock(). The goroutines here were independently running, and once the mutex was locked only one of them was allowed to work; kind of like, "Whoever has the speaking stick may address the group" around a campfire. Mutexes are the speaking stick of Go applications!

Friday, April 8, 2016

Using Golang Mutexes on Structs

When creating a "thing" that I didn't want other functions or operations to touch when something else might be doing something that could affect that thing, I would create a variable...usually a global-scoped variable...that I'd set with a particular value. Then I'd have code check that variable before doing anything that might upset other functions by altering the state of data. I usually called this a flag, but I'm sure in some cases it was more appropriate to call it a semaphore or...I'm not sure. It's probably against "proper" coding standards to do that. But it seemed to work as long as I was careful and commented what I was doing.

Go has a mechanism in the "sync" package called a mutex, used to lock something against alterations when concurrent routines might try altering data. From what I could find it's often recommended that when possible you should use alternate methods like channels and waitgroups to guarantee concurrency doesn't upset your variables/structs/etc, but mutexes should be used for exclusive access when working on caches and variable state. 

But how do they work? As in, how should I model their behavior for implementation in my application?

Let's try some simple applications to see how mutexes work.

What I want to do is have a struct whose values are "protected" and altered by only one section of code at a time. Can a mutex do that? 

Test One

First test I'll spin off some goroutines to hammer a change on a struct, with another routine locking the struct.

// How do mutexes work on a struct? Let's see if this works the way I hope it does...
package main

import (
 "fmt"
 "sync"
 "time"
)

func main() {

 type ProtectThese struct {
  secure    sync.Mutex
  firstname string
  lastname  string
 }

 // Create an instance of the structs
 var protected ProtectThese

 // And a cheap flag for quitting the main() goroutine
 var Stop bool = false

 // What time is it?
 StartTime := time.Now()

 // Spin off a goroutine that just locks protected and waits
 go func() {

  // Lock it
  protected.secure.Lock()
        
        // Tell us when it was locked
        fmt.Println("Locked at " + time.Since(StartTime).String())

  // Create a timer
  WaitForIt := time.NewTimer(time.Minute * 1)
        
  // After the timer elapses
  <-WaitForIt.C
        
  // Unlock the struct
  protected.secure.Unlock()
        
  // All done
  return

 }()

 // Another goroutine will try writing a value to firstname
 go func() {
        
  // An infinite loop because...why not?
  for {
   protected.firstname = "John"
  }
        
 }()

 // This goroutine will write a value to lastname
 go func() {
        
  // See the previous routine
  for {
   protected.lastname = "Doe"
  }
        
 }()

 // And yet another goroutine does nothing but reads values from protected to the stdout
 go func() {

  // A couple quick flags
  var firstchanged bool = false
  var lastchanged bool = false

  // Create a ticker to check the status of the struct periodically
  ticker := time.NewTicker(time.Nanosecond * 5)

  for range ticker.C {
            
   if protected.firstname == "John" && firstchanged == false {
    // Did the first name get filled in?
    fmt.Println("Firstname changed at " + time.Since(StartTime).String())
    firstchanged = true
   }
            
   if protected.lastname == "Doe" && lastchanged == false {
    // Did the last name change?
    fmt.Println("Lastname changed at " + time.Since(StartTime).String())
    lastchanged = true
   }
            
   if firstchanged == true && lastchanged == true {
    // Both are done. Change the running flag.
    Stop = true
   }
            
  }
 }()

 // This basically spins wheels until the variable for stopping is set
 // Checks every 50 milliseconds to see if we should quit
 for Stop == false {
  Waiting := time.NewTimer(time.Millisecond * 50)
  <-Waiting.C
 }
}

What's happening here?

Main() has only a few jobs to perform. It creates a struct holding 2 strings and a mutex, it creates an instance of that struct, it gets the current time, and creates a little flag variable (old habits die hard) and then checks every 50 milliseconds for that variable to become true.

There are also 4 goroutines:
Goroutine(a) locks the mutex in the struct, prints out the time since Main took the current time that the lock was set, then sits for a minute before unlocking it.
Goroutine(b) keeps trying to set the firstname string in the struct to John.
Goroutine(c) keeps trying to set the lastname string in the struct to Doe.
Goroutine(d) checks every 5 nanoseconds whether the firstname and lastname have changed, and if they did, prints the time since main() set the current time that it was changed. When both firstname and lastname are set, goroutine(d) also sets the "Stop" variable telling main() to quit.

Pretty simple. What happens when it's run?

Locked at 27.549µs
Firstname changed at 174.431µs
Lastname changed at 251.301µs

That's...fast. It ran on the order of microseconds. Pretty good indication that goroutine(a)'s lock didn't stop goroutine(b) and (c) from altering the struct.

Test Two

Let's try something a little different.

// How do mutexes work on a struct? Let's see if this works the way I hope it does...
package main

import (
 "fmt"
 "sync"
 "time"
)

func main() {

 type ProtectThese struct {
  secure    sync.Mutex
  firstname string
  lastname  string
 }

 // Create an instance of the structs
 var protected ProtectThese

 // And a cheap flag for quitting the main() goroutine
 var Stop bool = false

 // What time is it?
 StartTime := time.Now()

 // Spin off a goroutine that just locks protected and waits
 go func() {

  // Lock it
  protected.secure.Lock()
        
        // Tell us when it was locked
        fmt.Println("Locked at " + time.Since(StartTime).String())

  // Create a timer
  WaitForIt := time.NewTimer(time.Minute * 1)
        
  // After the timer elapses
  <-WaitForIt.C
        
  // Unlock the struct
  protected.secure.Unlock()
        
  // All done
  return

 }()

 // Another goroutine will try writing a value to firstname
 go func() {
        
        // Let's wait a little bit before trying to set this.
        Pause := time.NewTimer(time.Second * 30)
        <-Pause.C
        
  // An infinite loop because...why not?
  for {
   protected.firstname = "John"
  }
        
 }()

 // This goroutine will write a value to lastname
 go func() {
        
  // See the previous routine
  for {
   protected.lastname = "Doe"
  }
        
 }()

 // And yet another goroutine does nothing but reads values from protected to the stdout
 go func() {

  // A couple quick flags
  var firstchanged bool = false
  var lastchanged bool = false

  // Create a ticker to check the status of the struct periodically
  ticker := time.NewTicker(time.Nanosecond * 5)

  for range ticker.C {
            
   if protected.firstname == "John" && firstchanged == false {
    // Did the first name get filled in?
    fmt.Println("Firstname changed at " + time.Since(StartTime).String())
    firstchanged = true
   }
            
   if protected.lastname == "Doe" && lastchanged == false {
    // Did the last name change?
    fmt.Println("Lastname changed at " + time.Since(StartTime).String())
    lastchanged = true
   }
            
   if firstchanged == true && lastchanged == true {
    // Both are done. Change the running flag.
    Stop = true
   }
            
  }
 }()

 // This basically spins wheels until the variable for stopping is set
 // Checks every 50 milliseconds to see if we should quit
 for Stop == false {
  Waiting := time.NewTimer(time.Millisecond * 50)
  <-Waiting.C
 }
}

What's happening here?

Not much has changed; I just altered goroutine(b) to have a 30 second pause. What happens when I run it?

Locked at 44.836µs
Lastname changed at 160.966µs
Firstname changed at 30.000173283s

Shows that the timers are working. Still shows the mutex isn't doing anything.

Test Three

Time to try wrapping one of the goroutines in a mutex lock.

// How do mutexes work on a struct? Let's see if this works the way I hope it does...
package main

import (
 "fmt"
 "sync"
 "time"
)

func main() {

 type ProtectThese struct {
  secure    sync.Mutex
  firstname string
  lastname  string
 }

 // Create an instance of the structs
 var protected ProtectThese

 // And a cheap flag for quitting the main() goroutine
 var Stop bool = false

 // What time is it?
 StartTime := time.Now()

 // Spin off a goroutine that just locks protected and waits
 go func() {

  // Lock it
  protected.secure.Lock()

  // Tell us when it was locked
  fmt.Println("Locked at " + time.Since(StartTime).String())

  // Create a timer
  WaitForIt := time.NewTimer(time.Minute * 1)

  // After the timer elapses
  <-WaitForIt.C

  // Unlock the struct
  protected.secure.Unlock()

  // All done
  return

 }()

 // Another goroutine will try writing a value to firstname
 go func() {

  // Set the lock here in addition to the previous goroutine
  protected.secure.Lock()

  // An infinite loop because...why not?
  for {
   protected.firstname = "John"
  }

  // Unlock
  protected.secure.Unlock()

 }()

 // This goroutine will write a value to lastname
 go func() {

  // See the previous routine
  for {
   protected.lastname = "Doe"
  }

 }()

 // And yet another goroutine does nothing but reads values from protected to the stdout
 go func() {

  // A couple quick flags
  var firstchanged bool = false
  var lastchanged bool = false

  // Create a ticker to check the status of the struct periodically
  ticker := time.NewTicker(time.Nanosecond * 5)

  for range ticker.C {

   if protected.firstname == "John" && firstchanged == false {
    // Did the first name get filled in?
    fmt.Println("Firstname changed at " + time.Since(StartTime).String())
    firstchanged = true
   }

   if protected.lastname == "Doe" && lastchanged == false {
    // Did the last name change?
    fmt.Println("Lastname changed at " + time.Since(StartTime).String())
    lastchanged = true
   }

   if firstchanged == true && lastchanged == true {
    // Both are done. Change the running flag.
    Stop = true
   }

  }
 }()

 // This basically spins wheels until the variable for stopping is set
 // Checks every 50 milliseconds to see if we should quit
 for Stop == false {
  Waiting := time.NewTimer(time.Millisecond * 50)
  <-Waiting.C
 }
}

What's happening here?

This time in addition to goroutine(a) setting the mutex, I added the mutex around goroutine(b) as well. This is not entirely safe in that there is a race condition; it appears that goroutine(a) is spun up faster than (b), so it sets the lock sooner in every test I've run. If something were to delay (a) running, (b) could get to it first. Just something to remember.

What happens when this one is run?

Locked at 23.15µs
Lastname changed at 114.786µs
Firstname changed at 1m0.000142691s

Ah-ha! Goroutine(b) is stuck until the lock set by (a) is unlocked! This confirms that the mutex isn't magically wrapping the struct and set by whatever calls it...it's more like a flag, and any code that might interfere with it must still be mindfully set to check that flag before altering things. In other words, if you want the struct to be protected, you still have to place checks in your code where the code might stomp on the state of the struct; the mutex doesn't lock the struct from random changes.

Some of the sources I found online could be interpreted as saying that the mutex only locks the data right under it (that seems strange?) in the declarations, which here would mean firstname is protected, but lastname isn't. Let's test that.

Test Four

// How do mutexes work on a struct? Let's see if this works the way I hope it does...
package main

import (
 "fmt"
 "sync"
 "time"
)

func main() {

 type ProtectThese struct {
  secure    sync.Mutex
  firstname string
  lastname  string
 }

 // Create an instance of the structs
 var protected ProtectThese

 // And a cheap flag for quitting the main() goroutine
 var Stop bool = false

 // What time is it?
 StartTime := time.Now()

 // Spin off a goroutine that just locks protected and waits
 go func() {

  // Lock it
  protected.secure.Lock()

  // Tell us when it was locked
  fmt.Println("Locked at " + time.Since(StartTime).String())

  // Create a timer
  WaitForIt := time.NewTimer(time.Minute * 1)

  // After the timer elapses
  <-WaitForIt.C

  // Unlock the struct
  protected.secure.Unlock()

  // All done
  return

 }()

 // Another goroutine will try writing a value to firstname
 go func() {

  // Set the lock here in addition to the previous goroutine
  protected.secure.Lock()

  // An infinite loop because...why not?
  for {
   protected.firstname = "John"
  }

  // Unlock
  protected.secure.Unlock()

 }()

 // This goroutine will write a value to lastname
 go func() {

  // Set the lock
  protected.secure.Lock()

  // See the previous routine
  for {
   protected.lastname = "Doe"
  }

  // Unlock
  protected.secure.Unlock()

 }()

 // And yet another goroutine does nothing but reads values from protected to the stdout
 go func() {

  // A couple quick flags
  var firstchanged bool = false
  var lastchanged bool = false

  // Create a ticker to check the status of the struct periodically
  ticker := time.NewTicker(time.Nanosecond * 5)

  for range ticker.C {

   if protected.firstname == "John" && firstchanged == false {
    // Did the first name get filled in?
    fmt.Println("Firstname changed at " + time.Since(StartTime).String())
    firstchanged = true
   }

   if protected.lastname == "Doe" && lastchanged == false {
    // Did the last name change?
    fmt.Println("Lastname changed at " + time.Since(StartTime).String())
    lastchanged = true
   }

   if firstchanged == true && lastchanged == true {
    // Both are done. Change the running flag.
    Stop = true
   }

  }
 }()

 // This basically spins wheels until the variable for stopping is set
 // Checks every 50 milliseconds to see if we should quit
 for Stop == false {
  Waiting := time.NewTimer(time.Millisecond * 50)
  <-Waiting.C
 }
}

What's happening here?

Both goroutines(b) and (c) are wrapped in the call to the mutex lock. Output from the application:

Locked at 24.157µs
Firstname changed at 1m0.000158927s
^C

Ooh. I had to control-C that. What happened?

The key probably lay in here:

 // Spin off a goroutine that just locks protected and waits
 go func() {

  // Lock it
  protected.secure.Lock()

  // Tell us when it was locked
  fmt.Println("Locked at " + time.Since(StartTime).String())

  // Create a timer
  WaitForIt := time.NewTimer(time.Minute * 1)

  // After the timer elapses
  <-WaitForIt.C

  // Unlock the struct
  protected.secure.Unlock()

  // All done
  return

 }()

 // Another goroutine will try writing a value to firstname
 go func() {

  // Set the lock here in addition to the previous goroutine
  protected.secure.Lock()

  // An infinite loop because...why not?
  for {
   protected.firstname = "John"
  }

  // Unlock
  protected.secure.Unlock()

 }()

Goroutine(a) locks the struct, waits a minute, then unlocks and quits. The goroutine is gone.

Goroutine(b) then gets the struct next; it locked the struct, then enters an infinite loop setting the firstname repeatedly. The unlock() is never called!

Let's try fixing that.

Test Five

// How do mutexes work on a struct? Let's see if this works the way I hope it does...
package main

import (
 "fmt"
 "sync"
 "time"
)

func main() {

 type ProtectThese struct {
  secure    sync.Mutex
  firstname string
  lastname  string
 }

 // Create an instance of the structs
 var protected ProtectThese

 // And a cheap flag for quitting the main() goroutine
 var Stop bool = false

 // What time is it?
 StartTime := time.Now()

 // Spin off a goroutine that just locks protected and waits
 go func() {

  // Lock it
  protected.secure.Lock()

  // Tell us when it was locked
  fmt.Println("Locked at " + time.Since(StartTime).String())

  // Create a timer
  WaitForIt := time.NewTimer(time.Minute * 1)

  // After the timer elapses
  <-WaitForIt.C

  // Unlock the struct
  protected.secure.Unlock()

  // All done
  return

 }()

 // Another goroutine will try writing a value to firstname
 go func() {

  // Set the lock here in addition to the previous goroutine
  protected.secure.Lock()

  // Loop to set the firstname
  for protected.firstname != "John" {
   protected.firstname = "John"
  }

  // Unlock
  protected.secure.Unlock()

 }()

 // This goroutine will write a value to lastname
 go func() {

  // Set the lock
  protected.secure.Lock()

  // See the previous routine
  for protected.lastname != "Doe" {
   protected.lastname = "Doe"
  }

  // Unlock
  protected.secure.Unlock()

 }()

 // And yet another goroutine does nothing but reads values from protected to the stdout
 go func() {

  // A couple quick flags
  var firstchanged bool = false
  var lastchanged bool = false

  // Create a ticker to check the status of the struct periodically
  ticker := time.NewTicker(time.Nanosecond * 5)

  for range ticker.C {

   if protected.firstname == "John" && firstchanged == false {
    // Did the first name get filled in?
    fmt.Println("Firstname changed at " + time.Since(StartTime).String())
    firstchanged = true
   }

   if protected.lastname == "Doe" && lastchanged == false {
    // Did the last name change?
    fmt.Println("Lastname changed at " + time.Since(StartTime).String())
    lastchanged = true
   }

   if firstchanged == true && lastchanged == true {
    // Both are done. Change the running flag.
    Stop = true
   }

  }
 }()

 // This basically spins wheels until the variable for stopping is set
 // Checks every 50 milliseconds to see if we should quit
 for Stop == false {
  Waiting := time.NewTimer(time.Millisecond * 50)
  <-Waiting.C
 }
}

What's happening here?

Just added a quick check in the goroutines that set firstname and lastname so once the variable has the value set, they unlock and quit. Running the application yields the following output:

Locked at 30.974µs
Firstname changed at 1m0.000698523s
Lastname changed at 1m0.000794631s

That seems to show that yup, it locks for both those values in the struct.

So at this point it seems that you can lock the whole struct by just have a sync.Mutex included, and it's safe from alterations from code that you specifically wrap in a call to lock and unlock; if you forget, though, code that isn't wrapped in a fuzzy lock() blankie will merrily alter the values of your struct without batting an eye.

One last thing...is code trying to do something to the struct blocked, like channels get blocked waiting for a message to be pulled? Or do they try repeatedly? What does goroutine(b) do as it's currently written?

Test Six

 // Another goroutine will try writing a value to firstname
 go func() {

  // Announce what I'm doing
  fmt.Println("About to lock struct so I can change firstname at " + time.Since(StartTime).String())

  // Set the lock here in addition to the previous goroutine
  protected.secure.Lock()

  // I locked it!
  fmt.Println("Locked struct to change firstname at " + time.Since(StartTime).String())

  // Loop to set the firstname
  for protected.firstname != "John" {
   protected.firstname = "John"
  }

  // About to unlock
  fmt.Println("About to unlock struct for firstname at " + time.Since(StartTime).String())

  // Unlock
  protected.secure.Unlock()

  // And done...
  fmt.Println("Finished with altering firstname at " + time.Since(StartTime).String())

 }()

What's happening here?

All I've changed is goroutine(b) so it has some additional announcements to STDOUT. Here's what the new output says:

Locked at 25.739µs
About to lock struct so I can change firstname at 121.747µs
Lastname changed at 1m0.000195611s
Locked struct to change firstname at 1m0.000158478s
Firstname changed at 1m0.000593511s
About to unlock struct for firstname at 1m0.000590839s
Finished with altering firstname at 1m0.000960257s

To me this shows that the mutex blocks access; the process just waits. But that could be because of the structure of the code; let's try constantly hammering it in a loop again.

Test Seven

 // Another goroutine will try writing a value to firstname
 go func() {

  // Loop to set the firstname
  for protected.firstname != "John" {
   // Announce what I'm doing
   fmt.Println("About to lock struct so I can change firstname at " + time.Since(StartTime).String())

   // Set the lock here in addition to the previous goroutine
   protected.secure.Lock()

   // I locked it!
   fmt.Println("Locked struct to change firstname at " + time.Since(StartTime).String())

   // Make the change
   protected.firstname = "John"

   // About to unlock
   fmt.Println("About to unlock struct for firstname at " + time.Since(StartTime).String())

   // Unlock
   protected.secure.Unlock()

   // And done...
   fmt.Println("Finished with altering firstname at " + time.Since(StartTime).String())
  }

 }()

What's happening here?

Once again it's a relatively minor change in goroutine(b); now everything is encased in a loop instead of just the "let's make a change" bit. What is the output?

Locked at 36.342µs
About to lock struct so I can change firstname at 155.914µs
Lastname changed at 1m0.000200095s
Locked struct to change firstname at 1m0.000167036s
Firstname changed at 1m0.001612157s
About to unlock struct for firstname at 1m0.001605558s
Finished with altering firstname at 1m0.003361782s

Still blocking while the lock is set; it's not constantly retrying the loop or the "About to lock" message would keep repeating. I'm fairly confident that if you have a second process trying to do something on a struct you've locked from another process, it'll just block until the mutex is unlocked!

One last bit of fun, just to see what effect it would have; I wrapped the routine that checked for the status of the struct in a lock vs. no lock to see how many times it checked (after lowering the lock from goroutine(a) to 5 seconds);


 // And yet another goroutine does nothing but reads values from protected to the stdout
 go func() {

  // A couple quick flags
  var firstchanged bool = false
  var lastchanged bool = false

  // Create a ticker to check the status of the struct periodically
  ticker := time.NewTicker(time.Nanosecond * 5)

  for range ticker.C {

   // Add one to the counter
   counter = counter + 1

            // Lock it
            //protected.secure.Lock()
            
   if protected.firstname == "John" && firstchanged == false {
    // Did the first name get filled in?
    fmt.Println("Firstname changed at " + time.Since(StartTime).String())
    firstchanged = true
   }

   if protected.lastname == "Doe" && lastchanged == false {
    // Did the last name change?
    fmt.Println("Lastname changed at " + time.Since(StartTime).String())
    lastchanged = true
   }

   if firstchanged == true && lastchanged == true {
    // Both are done. Change the running flag.
    Stop = true
   }
            
            // Unlock it
            //protected.secure.Unlock()

  }
 }()

You can see the part I commented out, of course, to enable to lock. The results were kind of interesting (I assume it's because the check just blocked for the vast majority of 5 seconds...)

Without the lock: "I checked the status of the struct 124 times."
With the lock: "I checked the status of the struct 222896 times."

Maybe something to keep in mind if you have mutexes, a number of goroutines hitting excluded data, and performance issues!